search

e-mission / e-mission-docs

Repository for docs and issues. If you need help, please file an issue here. Public conversations are better for open source projects than private email.
https://e-mission.readthedocs.io/en/latest
BSD 3-Clause "New" or "Revised" License
15 stars 34 forks source link

Foreground service destroyed and not restarted when Google Chrome is updated #580

Closed shankari closed 4 years ago

shankari commented 4 years ago

This is a very tricky bug, and is going to be very hard to reproduce.

One of the test users reported that they didn't see any trips today. They also reported that they didn't see the foreground notification. The error in trip tracking was clearly due to the lack of foreground notification, but why was the foreground notification not showing up?

This is because when the Google system services are updated, the ForegroundService is killed and restarted. But the restart does not call onStartCommand. So the service does not show a notification and is not in the foreground. So it is destroyed almost immediately.

EDIT: Steps to reproduce

NOTE: This may only be due to memory pressure, not Google System updates. However, I am unable to reproduce this using memory pressure alone (I have opened 6 tabs in chrome in parallel: nytimes, washingtonpost, slate, salon, sfgate and mercurynews and the app is not killed).

I have now reproduced this ~ 5 times while testing out a fix. The problem is with Google Chrome. When Google Chrome is updated, the service is terminated.

shankari commented 4 years ago

First, let's confirm that the foreground notification was not showing up. Consistent with #567, the trip end is not detected for multiple days.

83915,1600451054.976,2020-09-18T11:44:14.976000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.ongoing_trip"
83947,1600451236.7910001,2020-09-18T11:47:16.791000-06:00,"LocationChangeIntentService : FINALLY! Got location update,"
... multiple lines with currState = ongoing_trip, but no actual location points ....
91754,1601074377.451,2020-09-25T16:52:57.451000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.ongoing_trip"
shankari commented 4 years ago

Next, we look to see what happened around 2020-09-18T11:47:16.791000-06:00. This is actually pretty weird. We didn't do anything. The app version was unchanged.

83973,1600453303.524,2020-09-18T12:21:43.524000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
83974,1600453303.5270002,2020-09-18T12:21:43.527000-06:00,LocationHandler : default request is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=3600000ms fastest=600000ms]
83975,1600453303.529,2020-09-18T12:21:43.529000-06:00,"LocationHandler : after applying config, value is Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]"
83976,1600453303.53,2020-09-18T12:21:43.530000-06:00,SensorControlBackgroundChecker : Checking location settings and permissions for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]
83977,1600453303.533,2020-09-18T12:21:43.533000-06:00,SensorControlBackgroundChecker : checkSelfPermission returned 0
83978,1600453303.536,2020-09-18T12:21:43.536000-06:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
83979,1600453303.5370002,2020-09-18T12:21:43.537000-06:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
83980,1600453303.5410001,2020-09-18T12:21:43.541000-06:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@24ff164
83981,1600453303.545,2020-09-18T12:21:43.545000-06:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
83982,1600453303.5579998,2020-09-18T12:21:43.558000-06:00,TripDiaryStateMachineRcvr : Comparing installed version 5 with new version 5
83983,1600453303.566,2020-09-18T12:21:43.566000-06:00,"TripDiaryStateMachineRcvr : Setup complete, skipping initialize"
83984,1600453303.583,2020-09-18T12:21:43.583000-06:00,BuiltinUserCache : Added value for key background/battery at time 1.600453303576E9
83985,1600453303.5870001,2020-09-18T12:21:43.587000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
83986,1600453303.6079998,2020-09-18T12:21:43.608000-06:00,ServerSyncAdapter : Starting sync with push
83987,1600453303.6139998,2020-09-18T12:21:43.614000-06:00,"BuiltinUserCache : While searching for regex of last transition, got 0 results"
83988,1600453303.6179998,2020-09-18T12:21:43.618000-06:00,"BuiltinUserCache : While searching for all, got 1 results"
83989,1600453303.6220002,2020-09-18T12:21:43.622000-06:00,"BuiltinUserCache : Considering transition 1.600451054666E9: {""currState"":""local.state.waiting_for_trip_start"",""transition"":""local.transition.exited_geofence"",""ts"":1.600451054666E9}"
83990,1600453303.6260002,2020-09-18T12:21:43.626000-06:00,BuiltinUserCache : Last trip end was at -1.0
83991,1600453303.6279998,2020-09-18T12:21:43.628000-06:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"

Everything still looks fine.

84024,1600457373.17,2020-09-18T13:29:33.170000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84025,1600457373.208,2020-09-18T13:29:33.208000-06:00,LocationHandler : default request is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=3600000ms fastest=600000ms]
84026,1600457373.2629998,2020-09-18T13:29:33.263000-06:00,"LocationHandler : after applying config, value is Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]"
84027,1600457373.2979999,2020-09-18T13:29:33.298000-06:00,SensorControlBackgroundChecker : Checking location settings and permissions for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]
84028,1600457373.3379998,2020-09-18T13:29:33.338000-06:00,SensorControlBackgroundChecker : checkSelfPermission returned 0
84029,1600457373.3979998,2020-09-18T13:29:33.398000-06:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
84030,1600457373.421,2020-09-18T13:29:33.421000-06:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
84031,1600457373.438,2020-09-18T13:29:33.438000-06:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@24ff164
84032,1600457373.573,2020-09-18T13:29:33.573000-06:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
84033,1600457373.573,2020-09-18T13:29:33.573000-06:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
84034,1600457373.619,2020-09-18T13:29:33.619000-06:00,SensorControlBackgroundChecker : Current location settings are com.google.android.gms.location.LocationSettingsResponse@27f3bc9
84035,1600457373.6239998,2020-09-18T13:29:33.624000-06:00,NotificationHelper : Cancelling notify with id 87225377
84036,1600457373.7020001,2020-09-18T13:29:33.702000-06:00,TripDiaryStateMachineRcvr : Comparing installed version 5 with new version 5
84037,1600457373.7029998,2020-09-18T13:29:33.703000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.ongoing_trip"
84038,1600457373.714,2020-09-18T13:29:33.714000-06:00,"TripDiaryStateMachineRcvr : Setup complete, skipping initialize"
84039,1600457373.772,2020-09-18T13:29:33.772000-06:00,BuiltinUserCache : Added value for key background/battery at time 1.600457373767E9
84040,1600457373.803,2020-09-18T13:29:33.803000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

Everything still looks fine.

84075,1600460774.1820002,2020-09-18T14:26:14.182000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84076,1600460774.187,2020-09-18T14:26:14.187000-06:00,LocationHandler : default request is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=3600000ms fastest=600000ms]
84077,1600460774.191,2020-09-18T14:26:14.191000-06:00,"LocationHandler : after applying config, value is Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]"
84078,1600460774.194,2020-09-18T14:26:14.194000-06:00,SensorControlBackgroundChecker : Checking location settings and permissions for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]
84079,1600460774.198,2020-09-18T14:26:14.198000-06:00,SensorControlBackgroundChecker : checkSelfPermission returned 0
84080,1600460774.201,2020-09-18T14:26:14.201000-06:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
84081,1600460774.2020001,2020-09-18T14:26:14.202000-06:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
84082,1600460774.21,2020-09-18T14:26:14.210000-06:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@24ff164
84083,1600460774.214,2020-09-18T14:26:14.214000-06:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
84084,1600460774.225,2020-09-18T14:26:14.225000-06:00,TripDiaryStateMachineRcvr : Comparing installed version 5 with new version 5
84085,1600460774.232,2020-09-18T14:26:14.232000-06:00,"TripDiaryStateMachineRcvr : Setup complete, skipping initialize"
84086,1600460774.24,2020-09-18T14:26:14.240000-06:00,BuiltinUserCache : Added value for key background/battery at time 1.600460774237E9
84087,1600460774.2429998,2020-09-18T14:26:14.243000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
84088,1600460774.2510002,2020-09-18T14:26:14.251000-06:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
84089,1600460774.2670002,2020-09-18T14:26:14.267000-06:00,SensorControlBackgroundChecker : Current location settings are com.google.android.gms.location.LocationSettingsResponse@27f3bc9
84090,1600460774.2710001,2020-09-18T14:26:14.271000-06:00,NotificationHelper : Cancelling notify with id 87225377

Everything is still valid.

84126,1600464426.4970002,2020-09-18T15:27:06.497000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84127,1600464426.512,2020-09-18T15:27:06.512000-06:00,LocationHandler : default request is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=3600000ms fastest=600000ms]
84128,1600464426.529,2020-09-18T15:27:06.529000-06:00,"LocationHandler : after applying config, value is Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]"
84129,1600464426.536,2020-09-18T15:27:06.536000-06:00,SensorControlBackgroundChecker : Checking location settings and permissions for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]
84130,1600464426.546,2020-09-18T15:27:06.546000-06:00,SensorControlBackgroundChecker : checkSelfPermission returned 0
84131,1600464426.554,2020-09-18T15:27:06.554000-06:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
84132,1600464426.56,2020-09-18T15:27:06.560000-06:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
84133,1600464426.575,2020-09-18T15:27:06.575000-06:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@24ff164
84134,1600464426.585,2020-09-18T15:27:06.585000-06:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
84135,1600464426.635,2020-09-18T15:27:06.635000-06:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
84136,1600464426.6379998,2020-09-18T15:27:06.638000-06:00,TripDiaryStateMachineRcvr : Comparing installed version 5 with new version 5
84137,1600464426.6479998,2020-09-18T15:27:06.648000-06:00,SensorControlBackgroundChecker : Current location settings are com.google.android.gms.location.LocationSettingsResponse@27f3bc9
84138,1600464426.661,2020-09-18T15:27:06.661000-06:00,"TripDiaryStateMachineRcvr : Setup complete, skipping initialize"
84139,1600464426.6729999,2020-09-18T15:27:06.673000-06:00,NotificationHelper : Cancelling notify with id 87225377
84140,1600464426.685,2020-09-18T15:27:06.685000-06:00,BuiltinUserCache : Added value for key background/battery at time 1.60046442668E9
84141,1600464426.686,2020-09-18T15:27:06.686000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.ongoing_trip"
84142,1600464426.704,2020-09-18T15:27:06.704000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

Here's where we upgrade the app from v5 to v7.

84177,1600468176.214,2020-09-18T16:29:36.214000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84178,1600468176.2770002,2020-09-18T16:29:36.277000-06:00,LocationHandler : default request is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=3600000ms fastest=600000ms]
84179,1600468176.323,2020-09-18T16:29:36.323000-06:00,"LocationHandler : after applying config, value is Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]"
84180,1600468176.3679998,2020-09-18T16:29:36.368000-06:00,SensorControlBackgroundChecker : Checking location settings and permissions for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]
84181,1600468176.4020002,2020-09-18T16:29:36.402000-06:00,SensorControlBackgroundChecker : checkSelfPermission returned 0
84182,1600468176.4229999,2020-09-18T16:29:36.423000-06:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
84183,1600468176.4429998,2020-09-18T16:29:36.443000-06:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
84184,1600468176.486,2020-09-18T16:29:36.486000-06:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@24ff164
84185,1600468176.5029998,2020-09-18T16:29:36.503000-06:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
84186,1600468176.5310001,2020-09-18T16:29:36.531000-06:00,TripDiaryStateMachineRcvr : Comparing installed version 5 with new version 7
84187,1600468176.542,2020-09-18T16:29:36.542000-06:00,"TripDiaryStateMachineRcvr : Setup not complete, sending initialize"
84188,1600468176.59,2020-09-18T16:29:36.590000-06:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
84189,1600468176.6629999,2020-09-18T16:29:36.663000-06:00,SensorControlBackgroundChecker : Current location settings are com.google.android.gms.location.LocationSettingsResponse@27f3bc9
84190,1600468176.6629999,2020-09-18T16:29:36.663000-06:00,BuiltinUserCache : Added value for key background/battery at time 1.600468176584E9
84191,1600468176.7189999,2020-09-18T16:29:36.719000-06:00,NotificationHelper : Cancelling notify with id 87225377
84192,1600468177.137,2020-09-18T16:29:37.137000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
shankari commented 4 years ago

Let's see what is happening with the foreground services. Aha! The foreground service was destroyed around the time we stopped getting the updates.

83934,1600451172.4420002,2020-09-18T11:46:12.442000-06:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
83935,1600451172.5979998,2020-09-18T11:46:12.598000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

when the app is upgraded

84186,1600468176.5310001,2020-09-18T16:29:36.531000-06:00,TripDiaryStateMachineRcvr : Comparing installed version 5 with new version 7
84187,1600468176.542,2020-09-18T16:29:36.542000-06:00,"TripDiaryStateMachineRcvr : Setup not complete, sending initialize"
84210,1600468179.776,2020-09-18T16:29:39.776000-06:00,TripDiaryStateMachineForegroundService : onStartCommand called with intent = Intent  flags = 0 and startId = 1

it is in ongoing_trip, so we don't restart the tracking

But why do we need to restart the tracking?

I guess because of the upgrade. We need to recreate the geofences on upgrade, so maybe we need to recreate the LocationChangesListener as well when we are in the ongoing_trip state? We should test this.

If we have a foreground service with a notification, why don't we start getting location points again? This may be because of the recreation needed above.

But then why did the user report that there was no notification?

We then get a bunch of other restarts. At least one of them should have generated a notification?

84354,1600481073.811,2020-09-18T20:04:33.811000-06:00,TripDiaryStateMachineForegroundService : onStartCommand called with intent = null flags = 0 and startId = 2
84474,1600489154.831,2020-09-18T22:19:14.831000-06:00,TripDiaryStateMachineForegroundService : onStartCommand called with intent = null flags = 0 and startId = 3
85293,1600549096.168,2020-09-19T14:58:16.168000-06:00,TripDiaryStateMachineForegroundService : onStartCommand called with intent = null flags = 0 and startId = 4
85893,1600592835.779,2020-09-20T03:07:15.779000-06:00,TripDiaryStateMachineForegroundService : onStartCommand called with intent = null flags = 0 and startId = 5
shankari commented 4 years ago

Summary so far:

shankari commented 4 years ago

I've tried many user-controlled options to kill the foreground service.

09-25 18:48:22.822 18705 18705 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-25 18:48:22.831 18705 18705 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.ongoing_trip starting foreground service
09-25 18:48:22.939 18705 18705 D TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
09-25 18:48:22.952 18705 18705 E ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@b98a515
09-25 18:48:23.482 18705 18705 D ForegroundServiceComm: Service successfully bound, setting state
09-25 18:48:23.576 18705 18705 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service
09-25 18:52:38.944  2051  2087 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-25 18:52:38.947  2051  2087 I ActivityManager:   Force stopping service ServiceRecord{dc4a239 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
shankari commented 4 years ago

Turned off location permissions, service crashed but no destroy.

2020-09-25 20:56:50.995 11866-11866/gov.colorado.energyoffice.emission D/ForegroundServiceComm: Service successfully bound, setting state
2020-09-25 20:56:51.286 11866-11866/gov.colorado.energyoffice.emission D/ForegroundServiceComm: Destroying FSM service, unbinding foreground service
2020-09-25 20:56:53.908 11866-11866/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 3
2020-09-25 20:56:53.928 11866-11866/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service
2020-09-25 20:58:16.910 2058-3393/? W/ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
2020-09-25 20:58:17.564 2058-2074/? I/ActivityManager:   Force stopping service ServiceRecord{dcf72e6 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
shankari commented 4 years ago

I also noticed some communication errors, but they seem to be intermittent, and bucketed by successful calls, so that was not the problem.

84236,1600471481.5370002,2020-09-18T17:24:41.537000-06:00,ServerSyncAdapter : Starting sync with push
84243,1600471481.575,2020-09-18T17:24:41.575000-06:00,"ServerSyncAdapter : Push complete, now pulling"
84248,1600471481.6929998,2020-09-18T17:24:41.693000-06:00,ServerSyncAdapter : IO Error org.apache.http.conn.HttpHostConnectException: Connection to https://api.canbikeco.org refused while posting converted trips to JSON
84250,1600471481.7270002,2020-09-18T17:24:41.727000-06:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

84254,1600475371.804,2020-09-18T18:29:31.804000-06:00,"ServerSyncAdapter : introDoneResult = {""intro_done"":""2020-09-09T16:28:31-06:00""}"
84272,1600475375.728,2020-09-18T18:29:35.728000-06:00,ServerSyncAdapter : Starting sync with push
84279,1600475375.9910002,2020-09-18T18:29:35.991000-06:00,"ServerSyncAdapter : Push complete, now pulling"
84301,1600475377.3539999,2020-09-18T18:29:37.354000-06:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

I get similar errors in the emulator while connected to the VPN, and that may be a similar issue here. At any rate, this is not the main issue.

shankari commented 4 years ago

Digging further into the trip start at around 11:47, we got a GeofenceExit, but with a bad quality point (hAcc=257)

83858,1600451054.55,2020-09-18T11:44:14.550000-06:00,GeofenceExitIntentService : onCreate called
83859,1600451054.564,2020-09-18T11:44:14.564000-06:00,GeofenceExitIntentService : onStartCommand called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.GeofenceExitIntentService (has extras) } flags 0 startId 1
83860,1600451054.5670002,2020-09-18T11:44:14.567000-06:00,GeofenceExitIntentService : onStart called with startId 1
83861,1600451054.571,2020-09-18T11:44:14.571000-06:00,GeofenceExitIntentService : geofence exit intent action = null
83862,1600451054.5839999,2020-09-18T11:44:14.584000-06:00,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@a74c30c
83863,1600451054.5870001,2020-09-18T11:44:14.587000-06:00,"GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused LAT,LON hAcc=257 et=+7d2h55m53s33ms alt=1601.699951171875 vAcc=2 sAcc=-1 bAcc=-1 {Bundle[mParcelledData.dataSize=52]}]"
83864,1600451054.591,2020-09-18T11:44:14.591000-06:00,GeofenceExitIntentService : Geofence exited! Intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.GeofenceExitIntentService (has extras) } Starting ongoing monitoring...
83872,1600451054.6460001,2020-09-18T11:44:14.646000-06:00,GeofenceExitIntentService : onDestroy called

At this point, the ForegroundService was fine.

83886,1600451054.688,2020-09-18T11:44:14.688000-06:00,ForegroundServiceComm : Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@d9d2ddd
83889,1600451054.7270002,2020-09-18T11:44:14.727000-06:00,"ForegroundServiceComm : Service successfully bound, setting state"
...
83908,1600451054.964,2020-09-18T11:44:14.964000-06:00,"ForegroundServiceComm : Destroying FSM service, unbinding foreground service"

We got two location points, but they were both of poor quality, and the LAT, LON values were identical

83905,1600451054.958,2020-09-18T11:44:14.958000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent { }"
83909,1600451054.966,2020-09-18T11:44:14.966000-06:00,"LocationChangeIntentService : Read locations [Location[fused LAT,LON hAcc=257 et=+7d2h55m53s33ms alt=1601.699951171875 vAcc=2 sAcc=-1 bAcc=-1 {Bundle[mParcelledData.dataSize=52]}]] from intent"

83924,1600451054.994,2020-09-18T11:44:14.994000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent { }"
83926,1600451054.9970002,2020-09-18T11:44:14.997000-06:00,LocationChangeIntentService : Read locations null from intent
83927,1600451054.998,2020-09-18T11:44:14.998000-06:00,LocationChangeIntentService : availability = true

83947,1600451236.7910001,2020-09-18T11:47:16.791000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent { }"
"LocationChangeIntentService : Read locations [Location[fused LAT,LON hAcc=15532 et=+7d2h58m55s305ms alt=1601.699951171875 vAcc=2 sAcc=-1 bAcc=-1 {Bundle[mParcelledData.dataSize=52]}]] from intent"

This seems to indicate that something else triggered the location code and not a real trip start. Could it be an OS update? A Google Play Services update?

shankari commented 4 years ago

Trying on the exact version of the OS used by the user. First, let's check the OS version...

Up until just before the change, it was 8.1.0.

2020-09-17T18:24:16.952000-06:00 1.0.0 8.1.0
2020-09-17T18:24:21.950000-06:00 1.0.0 8.1.0
2020-09-17T18:24:22.240000-06:00 1.0.0 8.1.0

Using the 8.1.0 emulator:

09-26 08:12:52.568  1635  1649 I ActivityManager: Start proc 16993:gov.colorado.energyoffice.emission/u0a81 f
or service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiarySt
ateMachineForegroundService
09-26 08:12:52.583 16993 16993 W zygote  : Unexpected CPU variant for X86 using defaults: x86
09-26 08:12:52.614  1635  1861 I ActivityManager: Force stopping gov.colorado.energyoffice.emission appid=100
81 user=0: from pid 17007
09-26 08:12:52.615  1635  1861 I ActivityManager: Killing 16993:gov.colorado.energyoffice.emission/u0a81 (adj
 200): stop gov.colorado.energyoffice.emission
09-26 08:12:52.616  1635  1651 W zygote  : kill(-16993, 9) failed: No such process
09-26 08:12:52.616  1635  1861 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyof
fice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4
000ms
09-26 08:12:52.619  1635  1861 I ActivityManager:   Force stopping service ServiceRecord{acc637c u0 gov.color
ado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForeground
Service}
09-26 08:12:52.632  1838  1838 D CarrierSvcBindHelper: No carrier app for: 0
09-26 08:12:52.638  1732  1732 W StatusBar: removeNotification for unknown key: 0|gov.colorado.energyoffice.e
mission|6646464|null|10081
shankari commented 4 years ago

Trying to upgrade all installed apps. I hope this will upgrade Google Play Services as well since I don't see it as an explicit update option.

Ah, this seems to have done something to the service (I don't see the notification any more). BINGO!

2020-09-26 09:47:48.498 18078-18078/? D/TripDiaryStateMachineForegroundService: onDestroy called for foreground service
2020-09-26 09:47:48.526 18078-18078/? D/TripDiaryStateMachineForegroundService: onDestroy called, removing notification

Let us wait a bit and see whether it ever restarts. But I am guessing not.

shankari commented 4 years ago

More detail from the logcat. It looks like when the process is restarted, we don't even get an onStartCommand, so we don't generate the notification. And then because the service doesn't have a notification, it is destroyed.

09-26 09:47:37.166  1635  1649 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 10991ms
09-26 09:47:48.169  1635  1649 I ActivityManager: Start proc 18078:gov.colorado.energyoffice.emission/u0a81 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-26 09:47:48.214  1635  7066 W ActivityManager: Stopping service due to app idle: u0a81 -17m26s27ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-26 09:47:48.498 18078 18078 D TripDiaryStateMachineForegroundService: onDestroy called for foreground service
09-26 09:47:48.526 18078 18078 D TripDiaryStateMachineForegroundService: onDestroy called, removing notification
shankari commented 4 years ago

Some more testing before we can figure out how to best to fix this

Is this 100% reproducible on 8.1.0?

Yes, and the download doesn't appear to be Google Play Services. When I started from a wiped emulator, I got multiple messages saying that Google Play Services needed to be updated. But the foreground service was still killed, around the time the 37th dependency was updated

09-26 10:42:30.325  2330  6482 D DownloadManager: [37] Starting
09-26 10:42:51.920  2330  6482 D DownloadManager: [37] Finished with status SUCCESS
09-26 10:42:55.128  2330  3787 V DownloadManager: Deleting /storage/emulated/0/Android/data/com.android.vending/files/1601142150146 via provider delete
09-26 10:43:02.380  1657  1681 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 10990ms
...
09-26 10:43:03.620  2330  6739 D DownloadManager: [38] Starting
09-26 10:43:15.479  2330  6739 D DownloadManager: [38] Finished with status SUCCESS
09-26 10:43:18.260  2330  2342 V DownloadManager: Deleting /storage/emulated/0/Android/data/com.android.vending/files/1601142183438 via provider delete
09-26 10:43:37.238  2330  6838 D DownloadManager: [39] Starting
09-26 10:43:38.451  2330  6838 D DownloadManager: [39] Finished with status SUCCESS
09-26 10:43:45.906  2330  6059 V DownloadManager: Deleting /data/data/com.android.providers.downloads/cache/downloadfile-1.bin via provider delete
09-26 10:43:50.594  6504  6531 W GooglePlayServicesUtil: Google Play services out of date for com.google.android.apps.messaging.  Requires 11925000 but found 11580470
09-26 10:44:39.820  6446  6477 W GooglePlayServicesUtil: Google Play services out of date for com.google.android.apps.messaging.  Requires 11925000 but found 11580470
09-26 10:44:39.823  6446  6477 E GooglePlayServicesUtil: GooglePlayServices not available due to error 2

And after kill, when I went clicked on the alerts, Google Play Services still needed to be updated. After updating Google Play Services to 20.33.15 (Updated on Sep 9), initialized and got the notification back. Let's retry the remaining updates.

Remaining updates finished (including of the Google app) without restarting the service.

shankari commented 4 years ago

Let's apply the updates one by one to see which causes the foreground service to be killed, and whether that is deterministic. - While updating one by one, the foreground service was not killed.

$ egrep "Foreground.*onDestroy" /tmp/logcat.log | wc -l
       0

So maybe this is not related to an upgrade, but rather, to memory pressure caused by multiple simultaneous downloads.

logcat.log.gz

shankari commented 4 years ago

Forcing memory pressure in a device. https://stackoverflow.com/questions/15588625/how-can-i-force-memory-pressure-for-android-debugging

shankari commented 4 years ago

Let's verify this (memory pressure, not update) with another check.

First start

09-26 15:36:09.219  5636  5636 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 3
09-26 15:36:09.240  5636  5636 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-26 15:36:09.568  5636  5636 E ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@bc55cf8

First crash + destroy

09-26 15:38:53.506  1652  1679 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-26 15:38:54.518  1652  1679 I ActivityManager: Start proc 8307:gov.colorado.energyoffice.emission/u0a80 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-26 15:38:54.565  1652  1806 W ActivityManager: Stopping service due to app idle: u0a80 -3m44s241ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-26 15:38:54.800  8307  8307 D TripDiaryStateMachineForegroundService: onDestroy called for foreground service
09-26 15:38:54.855  8307  8307 D TripDiaryStateMachineForegroundService: onDestroy called, removing notification

Restart

09-26 15:40:13.358  8707  8707 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-26 15:40:13.382  8707  8707 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service
09-26 15:40:13.782  8707  8707 D TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
09-26 15:40:13.821  8707  8707 E ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@62690cb

I don't actually see a second crash in the logs; did that really happen? Should take a screenshot next time.

shankari commented 4 years ago

Reproduced: crashed after 5 updates (Maps, Text-to-Speech, Clock, Messages, Chrome). Chrome was the last update; the one that caused it to crash.

Let's move on to pure memory pressure to put it beyond all doubt.

shankari commented 4 years ago

The results of pure memory pressure are inconclusive.

09-26 16:06:18.382  1665  1679 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 10994ms
09-26 20:27:29.411  1665  2342 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-26 20:32:23.058  1665  4912 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms

The only consistent method to reproduce seems to be to update at the same time.

shankari commented 4 years ago

In terms of a fix, we have the STICKY flag set, and the service is indeed restarted. However, it doesn't call onStartCommand, so we don't send the service to the foreground.

use START_FLAG_REDELIVERY to have the system re-deliver an Intent for you so that it does not get lost if your service is killed while processing it.

Might this fix the problem?

shankari commented 4 years ago

Might this fix the problem?

Nope. It does not.

09-26 21:27:21.704  1666  1680 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 431604ms
09-26 21:27:22.635  1666  2312 I ActivityManager:   Force stopping service ServiceRecord{36e6e9c u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

431604 ms = 431604 / (1000 * 60) = 7 secs. The notification did not recur even by 21:45.

shankari commented 4 years ago

Searching specifically for the "Scheduling restart" threads on stackoverflow finds a lot of junk but also finds this https://stackoverflow.com/questions/12648447/why-does-my-android-service-get-restarted-when-the-process-is-killed-even-thoug

Let's try to add a callback to onCreate. If we get a callback, that is good enough since we can move the service to the foreground at that point. We should also use dumpsys to check the service settings. https://stackoverflow.com/a/14293528/4040267

shankari commented 4 years ago

dumpsys settings are fine

    *APP* UID 10080 ProcessRecord{115cbae 12490:gov.colorado.energyoffice.emission/u0a80}
    ...
    foregroundServices=true forcingToImportant=null
    hasStartedServices=true
    ...
    Proc #20: prcp  F/S/FGS  trm: 0 12490:gov.colorado.energyoffice.emission/u0a80 (fg-service)
shankari commented 4 years ago

Reverted back to START_STICKY, still getting the same logs. Cannot see onDestroy callback any more!

09-27 17:22:20.127  1665  1679 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 10994ms
09-27 17:22:24.806  1665  7524 I ActivityManager:   Force stopping service ServiceRecord{9d0287 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
shankari commented 4 years ago

While retrying, I get 

09-27 17:36:45.324  1663  1677 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-27 17:36:46.336  1663  1677 I ActivityManager: Start proc 8670:gov.colorado.energyoffice.emission/u0a81 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 17:36:46.472  1663  7350 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-27 17:36:46.479  1663  7350 I ActivityManager:   Force stopping service ServiceRecord{1a08e43 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
shankari commented 4 years ago

I saw that it once (https://github.com/e-mission/e-mission-docs/issues/580#issuecomment-699523619), but I haven't been able to see the onDestroy call ever again. Maybe this old version of ActivityManager doesn't call onDestroy but the version that I had before wiping data did? Note that I had upgraded a few months ago. Not sure how to restore to the version from a few months ago, though.

shankari commented 4 years ago

Aha! If I use the Android 9 emulator (API 28), and upgrade Google Chrome by downloading from apksfree, then I do get the onDestroy behavior.

09-27 18:47:31.985  1929  1943 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 20848ms
09-27 18:47:52.851  1929  3214 W ActivityManager: Stopping service due to app idle: u0a87 -5m25s546ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 18:47:52.871  1929  1945 I ActivityManager: Start proc 15872:gov.colorado.energyoffice.emission/u0a87 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 18:47:53.240 15872 15872 D TripDiaryStateMachineForegroundService: onDestroy called for foreground service
09-27 18:47:53.240 15872 15872 D TripDiaryStateMachineForegroundService: onDestroy called, removing notification

So it looks like:

logcat_android9_orig.log.gz

shankari commented 4 years ago

and on android 8 by updating everything other than google chrome and then upgrading chrome manually

This doesn't work. Upgrading chrome manually hangs. Have to test on android 9

shankari commented 4 years ago

Using --no-streaming, we get 

./adb install --no-streaming /tmp/com.android.chrome_v70.0.3538.64-353806400_Android-4.1.apk
Performing Push Install
/tmp/com.android.chrome_v70.0.3538.64-353806400_Andro...hed, 0 skipped. 119.6 MB/s (44596437 bytes in 0.356s)
Failure [INSTALL_FAILED_NO_MATCHING_ABIS: Failed to extract native libraries, res=-113]
shankari commented 4 years ago

Using the arm64-v8a architecture from apkpure worked for upgrading chrome. But the error was the same

09-27 21:12:46.346  1664  1678 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-27 21:12:46.558  1664  5818 I ActivityManager:   Force stopping service ServiceRecord{a3da6db u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

And after the upgrade, the app won't start, presumably because it is a bad version of Chrome. This also explains why the Chrome upgrade killed the app.

09-27 21:15:51.375 12030 12030 E WebViewFactory: java.lang.reflect.InvocationTargetException
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at java.lang.reflect.Method.invoke(Native Method)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebViewFactory.getProvider(WebViewFactory.java:208)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.getFactory(WebView.java:2530)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.ensureProviderCreated(WebView.java:2525)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.setOverScrollMode(WebView.java:2590)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.view.View.<init>(View.java:4574)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.view.View.<init>(View.java:4706)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.view.ViewGroup.<init>(ViewGroup.java:597)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.widget.AbsoluteLayout.<init>(AbsoluteLayout.java:55)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.<init>(WebView.java:643)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.<init>(WebView.java:588)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.<init>(WebView.java:571)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at android.webkit.WebView.<init>(WebView.java:558)
09-27 21:15:51.375 12030 12030 E WebViewFactory:    at org.apache.cordova.engine.SystemWebView.<init>(SystemWebView.java:47)

logcat_android8_updated.log.gz

shankari commented 4 years ago

This is absolutely unpredictable. logcat_android9_updated.log.gz

Recall that the original Chrome upgrade from 69 -> 70 called onDestroy

09-27 18:47:31.985  1929  1943 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 20848ms
09-27 18:47:52.851  1929  3214 W ActivityManager: Stopping service due to app idle: u0a87 -5m25s546ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 18:47:52.871  1929  1945 I ActivityManager: Start proc 15872:gov.colorado.energyoffice.emission/u0a87 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 18:47:53.240 15872 15872 D TripDiaryStateMachineForegroundService: onDestroy called for foreground service
09-27 18:47:53.240 15872 15872 D TripDiaryStateMachineForegroundService: onDestroy called, removing notification

Upgrading from 70 -> 71 in the same emulator, had this behavior

09-27 21:22:14.384  1929  3214 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-27 21:22:14.413  1929  3214 I ActivityManager:   Force stopping service ServiceRecord{99a1426 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

09-27 21:22:43.853 16754 16754 D TripDiaryStateMachineForegroundService: onCreate called
09-27 21:22:43.853 16754 16754 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1

After resetting the emulator, upgrading from 69 -> 70 had this behavior

09-27 21:30:33.720  1934  1949 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-27 21:30:34.738  1934  1951 I ActivityManager: Start proc 6362:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 21:30:35.068  6362  6362 D TripDiaryStateMachineForegroundService: onCreate called
09-27 21:30:35.069  6362  6362 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 5
09-27 21:30:35.101  6362  6362 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service
09-27 21:30:42.059  1934  2690 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-27 21:30:42.062  1934  2690 I ActivityManager:   Force stopping service ServiceRecord{a7f5cca u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

Going to play around some more with android 9, but it looks like we really can't assume that onDestroy will be called reliably.

logcat_android9_updated_after_reset.log.gz

shankari commented 4 years ago

Let's be more careful and write down the steps this time:

09-27 22:14:18.471  1926  1940 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-27 22:14:19.501  1926  1942 I ActivityManager: Start proc 7535:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 22:14:19.741  7535  7535 D TripDiaryStateMachineForegroundService: onCreate called
09-27 22:14:19.741  7535  7535 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 5
09-27 22:14:19.769  7535  7535 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service
09-27 22:14:32.922  1926  3772 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-27 22:14:32.937  1926  3772 I ActivityManager:   Force stopping service ServiceRecord{d847a9b u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

Last entries for ForegroundService:

09-27 22:17:35.795  8017  8017 E ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@fab6c78
09-27 22:17:36.030  8017  8017 D ForegroundServiceComm: Service successfully bound, setting state
09-27 22:17:36.062  8017  8017 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service
shankari commented 4 years ago

Quick check around context:

09-27 22:37:16.660  1929  7243 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-27 22:37:16.671  1929  7243 I ActivityManager:   Force stopping service ServiceRecord{5a77aa7 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
09-27 22:38:01.776  8401  8401 D TripDiaryStateMachineForegroundService: onCreate called
09-27 22:38:01.777  8401  8401 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-27 22:38:01.778  8401  8401 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-27 22:40:42.188  8401  8401 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
09-27 22:40:42.189  8401  8401 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-27 22:40:42.221  8401  8401 E ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@18a3b41
09-27 22:40:42.268  8401  8401 D ForegroundServiceComm: Service successfully bound, setting state
09-27 22:40:42.281  8401  8401 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service
09-27 22:43:06.479  1929  1943 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-27 22:43:07.486  1929  1956 W ActivityManager: Stopping service due to app idle: u0a86 -5m5s714ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 22:43:07.520  1929  1945 I ActivityManager: Start proc 8680:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 22:43:07.777  8680  8680 D TripDiaryStateMachineForegroundService: onCreate called
09-27 22:43:07.780  8680  8680 D TripDiaryStateMachineForegroundService: onDestroy called for foreground service
09-27 22:43:07.780  8680  8680 D TripDiaryStateMachineForegroundService: onDestroy called, removing notification

Why do only some chrome updates cause the service to be killed?

shankari commented 4 years ago

Another report from the same user 

91334,1601078825.032,2020-09-25T17:07:05.032000-07:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
91335,1601078825.039,2020-09-25T17:07:05.039000-07:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

This is definitely not related to the app upgrade in any way since we haven't pushed any updates since.

Checking the Google Chrome entry in the play store, it was last updated September 24, 2020, which would be consistent with an app rollout on the 25th.

EDIT: Confirmed with the user that Chrome was updated 3 days ago.

shankari commented 4 years ago

I wonder if this is related to the context for the service. In general, we start the service from the activity directly, which has Chrome in the context. Maybe sending a broadcast instead would work better?

When started directly from the activity, on consent, the context is

Application@12209

When started from the initialize callback, the context is

ReceiverRestrictedContext@12223

While I had a debugger connected and was writing this down, I got the following

2020-09-28 12:26:37.611 1933-1947/? W/ActivityManager: Bringing down service while still waiting for start foreground: ServiceRecord{957f364 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
2020-09-28 12:26:37.621 1933-1947/? I/ActivityManager: Skipping duplicate ANR: ProcessRecord{25a0fca 3908:gov.colorado.energyoffice.emission/u0a86} Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{957f364 u0}

2020-09-28 12:27:59.731 3908-3908/? D/TripDiaryStateMachineForegroundService: onDestroy called for foreground service
2020-09-28 12:27:59.732 3908-3908/? D/TripDiaryStateMachineForegroundService: onDestroy called, removing notification
2020-09-28 12:27:59.737 3908-3908/? E/AndroidRuntime: FATAL EXCEPTION: main
    Process: gov.colorado.energyoffice.emission, PID: 3908
    android.app.RemoteServiceException: Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{28fa935 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

We really need the logcat logs around this time as well.

shankari commented 4 years ago

Restarting with logs instead of debugger, I get

2020-09-28 12:33:29.232 7818-8017/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = android.app.Application@7e5e4e8
2020-09-28 12:33:29.236 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
2020-09-28 12:33:29.238 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

2020-09-28 12:33:30.686 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@19252a2
2020-09-28 12:33:30.691 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
2020-09-28 12:33:30.693 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

2020-09-28 12:34:00.734 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@19252a2
2020-09-28 12:34:00.737 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 3
2020-09-28 12:34:00.737 7818-7818/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
shankari commented 4 years ago

12:37: Updating Chrome 12:38: Killed + restarted service (could see little glitch) 12:39: Still visible 12:40: Still visible 12:41: Still visible

09-28 12:37:48.021  1933  1947 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 12:37:49.043  1933  1949 I ActivityManager: Start proc 8329:gov.colorado.energyoffice.emission/u0a87 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 12:37:49.244  8329  8329 D TripDiaryStateMachineForegroundService: onCreate called
09-28 12:37:49.245  8329  8329 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 4
09-28 12:37:49.268  8329  8329 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service

Let's see if this is just the context...

logcat.worked.1.log.gz

shankari commented 4 years ago

Repro 2: 12:45: First start of service

09-28 12:45:20.795  3844  3844 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@6b579d6
09-28 12:45:20.800  3844  3844 D TripDiaryStateMachineForegroundService: onCreate called
09-28 12:45:20.801  3844  3844 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-28 12:45:20.803  3844  3844 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

09-28 12:45:32.753  3844  3844 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
09-28 12:45:32.756  3844  3844 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

12:46: Fixed location settings, sent initialize

2020-09-28 12:46:37.317 3844-3844/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@6b579d6
2020-09-28 12:46:37.324 3844-3844/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 3
2020-09-28 12:46:37.324 3844-3844/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

12:50: Upgraded Chrome. Service killed. No restart.

09-28 12:50:16.061  1928  1942 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 12:50:16.407  1928  5240 I ActivityManager:   Force stopping service ServiceRecord{7d5013c u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}

12:51: Force sync. Service reappeared

09-28 12:51:35.435  8666  8797 D TripDiaryStateMachineForegroundService: In checkForegroundNotification, found 0 active notifications
09-28 12:51:35.436  8666  8797 D TripDiaryStateMachineForegroundService: Did not find foreground notification with ID 6646464 in list java.util.stream.ReferencePipeline$3@d6346fc
09-28 12:51:35.436  8666  8797 D TripDiaryStateMachineForegroundService: startProperly called with context = gov.colorado.energyoffice.emission.MainActivity@eb6995f
09-28 12:51:35.438  8666  8666 D TripDiaryStateMachineForegroundService: onCreate called
09-28 12:51:35.439  8666  8666 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-28 12:51:35.447  8666  8666 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service

12:52: Upgrade to v78. No crash. 12:55: Upgrade through Google Play. Killed again, but restarted!

09-28 12:56:01.994  1928  1955 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 20971ms
09-28 12:56:23.032  1928  1944 I ActivityManager: Start proc 10417:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 12:56:23.779 10417 10417 D TripDiaryStateMachineForegroundService: onCreate called
09-28 12:56:23.785 10417 10417 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 2
09-28 12:56:23.887 10417 10417 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.waiting_for_trip_start starting foreground service

So it looks like this is not a 100% fix, but it does seem to work more often?! And of course, the backup works pretty well.

2:26: Still up

09-28 13:40:21.051 10986 11003 D TripDiaryStateMachineForegroundService: In checkForegroundNotification, found 1 active notifications
09-28 13:40:21.052 10986 11003 D TripDiaryStateMachineForegroundService: Found foreground notification with ID 6646464 nothing to do

logcat.worked.2.log.gz

shankari commented 4 years ago

Repro 3: logcat.worked.3.log.gz

2:35: Started service (app is running in foreground) 2:36: Upgrade chrome -> Killed app, killed service

09-28 14:36:31.922  1929  1943 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 14:36:32.933  1929  1945 I ActivityManager: Start proc 6147:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 14:36:33.145  6147  6147 D TripDiaryStateMachineForegroundService: onCreate called
09-28 14:36:33.146  6147  6147 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 4
09-28 14:36:33.170  6147  6147 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 14:36:33.263  6147  6147 D ForegroundServiceComm: nRecursion = 1 rebinding
09-28 14:36:33.264  6147  6147 D TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
09-28 14:36:33.266  6147  6147 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service
09-28 14:36:35.454  1929  2092 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-28 14:36:35.455  1929  2092 I ActivityManager:   Force stopping service ServiceRecord{d2a68d0 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
shankari commented 4 years ago

Looking at the full logcat for the process

09-28 14:36:32.933  1929  1945 I ActivityManager: Start proc 6147:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 14:36:32.968  6147  6147 W office.emissio: Unexpected CPU variant for X86 using defaults: x86

We initialize the process

09-28 14:36:33.091  6147  6147 I FirebaseInitProvider: FirebaseApp initialization successful
09-28 14:36:33.106  6147  6147 I System.out: logger == null, lazily creating new logger
09-28 14:36:33.145  6147  6147 D TripDiaryStateMachineForegroundService: onCreate called
09-28 14:36:33.146  6147  6147 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 4
09-28 14:36:33.150  6147  6147 I System.out: logger == null, lazily creating new logger

We check for permissions

09-28 14:36:33.164  6147  6147 D SensorControlBackgroundChecker: Checking location settings and permissions for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]

Go to the foreground.

09-28 14:36:33.170  6147  6147 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

Generate the error notification.

09-28 14:36:33.230  6147  6147 D NotificationHelper: Generating notify with id 87225377, message Error 6 in location settings and pending intent PendingIntent{3e4d67f: android.os.BinderProxy@704364c}

Handle the tracking_error

09-28 14:36:33.236  6147  6147 I TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@15813aa, Intent { act=local.transition.tracking_error flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
09-28 14:36:33.253  6147  6147 D TripDiaryStateMachineService: handleAction(local.state.start, local.transition.tracking_error) called

09-28 14:36:33.266  6147  6147 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service

Then the force stop for the app is called.

09-28 14:36:35.453  1929  2092 I ActivityManager: Force stopping gov.colorado.energyoffice.emission appid=10086 user=0: from pid 6281

Which kills the service.

09-28 14:36:35.453  1929  2092 I ActivityManager: Killing 6147:gov.colorado.energyoffice.emission/u0a86 (adj 200): stop gov.colorado.energyoffice.emission
09-28 14:36:35.454  1929  1946 W libprocessgroup: kill(-6147, 9) failed: No such process
09-28 14:36:35.454  1929  2092 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-28 14:36:35.455  1929  2092 I ActivityManager:   Force stopping service ServiceRecord{d2a68d0 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
09-28 14:36:35.505  1771  1771 I Zygote  : Process 6147 exited due to signal (9)
09-28 14:36:35.543  1929  1946 W libprocessgroup: kill(-6147, 9) failed: No such process

But then why was the service killed in the first place?

shankari commented 4 years ago

Looks like this double dipping is because the app was first killed due chrome being killed and then killed because of chrome being replaced

09-28 14:35:38.854  1775  1972 V installed: DexInv: --- BEGIN '/data/app/gov.colorado.energyoffice.emission-ID6MGmzskTKXO7-EnwjRMw==/base.apk' ---
09-28 14:35:39.787  1775  1972 V installed: DexInv: --- END '/data/app/gov.colorado.energyoffice.emission-ID6MGmzskTKXO7-EnwjRMw==/base.apk' (success) ---

09-28 14:35:40.049  1929  6000 I BackgroundDexOptService: Pinning optimized code {gov.colorado.energyoffice.emission}
09-28 14:35:42.137  1770  2217 W SurfaceFlinger: Attempting to set client state on removed layer: gov.colorado.energyoffice.emission/gov.colorado.energyoffice.emission.MainActivity#1
09-28 14:35:42.137  1770  2217 W SurfaceFlinger: Attempting to destroy on removed layer: gov.colorado.energyoffice.emission/gov.colorado.energyoffice.emission.MainActivity#1

Force stopping

09-28 14:36:31.908  1929  1943 I ActivityManager: Force stopping com.android.chrome appid=10084 user=-1: installPackageLI
09-28 14:36:31.910  1929  1943 I ActivityManager: Killing 3949:gov.colorado.energyoffice.emission/u0a86 (adj 0): stop com.android.chrome
09-28 14:36:31.916  1929  1946 W libprocessgroup: kill(-3949, 9) failed: No such process
09-28 14:36:31.922  1929  1943 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 14:36:31.929  4060  4060 I cr_ChildProcessService: Destroying ChildProcessService pid=4060
09-28 14:36:31.938  1929  1943 W ActivityManager: Force removing ActivityRecord{b65cf17 u0 gov.colorado.energyoffice.emission/.MainActivity t6}: app died, no saved state

Reinstall complete

09-28 14:36:34.061  1929  1943 W BroadcastQueue: Background execution not allowed: receiving Intent { act=android.intent.action.PACKAGE_REPLACED dat=package:com.android.chrome flg=0x4000010 (has extras) } to com.google.android.ims/.receivers.RcsAutoStartReceiver

Restart again scheduled. But process is already dead.

09-28 14:36:35.454  1929  2092 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-28 14:36:35.455  1929  2092 I ActivityManager:   Force stopping service ServiceRecord{d2a68d0 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
09-28 14:36:35.500  1929  1946 W libprocessgroup: kill(-6147, 9) failed: No such process
09-28 14:36:35.505  1771  1771 I Zygote  : Process 6147 exited due to signal (9)

09-28 14:36:35.543  1929  1946 W libprocessgroup: kill(-6147, 9) failed: No such process
09-28 14:36:35.543  1929  1946 I libprocessgroup: Successfully killed process cgroup uid 10086 pid 6147 in 89ms
shankari commented 4 years ago

3:47: initial create, kill app activity 3:48: upgrade chrome, services are killed

logcat.worked.4.log.gz

09-28 15:47:23.121  3830  4663 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.Application@99dfbaf
09-28 15:47:23.124  3830  3830 D TripDiaryStateMachineForegroundService: onCreate called
09-28 15:47:23.126  3830  3830 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-28 15:47:23.129  3830  3830 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 15:47:25.458  3830  3830 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@4ed4ebc
09-28 15:47:25.463  3830  3830 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
09-28 15:47:25.463  3830  3830 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 15:47:25.523  3830  3830 D TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
09-28 15:47:25.834  3830  3830 D ForegroundServiceComm: Service successfully bound, setting state
09-28 15:47:25.853  3830  3830 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service

09-28 15:47:25.884  3830  3830 E ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@92d76a5
09-28 15:47:25.905  3830  3830 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service
09-28 15:48:40.784  1931  1945 I ActivityManager: Force stopping com.android.chrome appid=10085 user=-1: installPackageLI
09-28 15:48:40.788  1931  1945 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 15:48:41.801  1931  1947 I ActivityManager: Start proc 6818:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 15:48:42.033  6818  6818 D TripDiaryStateMachineForegroundService: onCreate called
09-28 15:48:42.035  6818  6818 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 3
09-28 15:48:42.081  6818  6818 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 15:48:42.142  1931  1958 I ActivityManager: Force stopping com.android.chrome appid=10085 user=0: pkg removed

09-28 15:48:42.256  6818  6818 D TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
09-28 15:48:42.269  6818  6818 D ForegroundServiceComm: Destroying FSM service, unbinding foreground service

09-28 15:48:44.387  1931  2761 I ActivityManager: Force stopping gov.colorado.energyoffice.emission appid=10086 user=0: from pid 6962
09-28 15:48:44.388  1931  2761 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 4000ms
09-28 15:48:44.389  1931  2761 I ActivityManager:   Force stopping service ServiceRecord{81ef97a u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
09-28 15:48:44.429  1931  1948 W libprocessgroup: kill(-6818, 9) failed: No such process
09-28 15:48:44.469  1931  1948 W libprocessgroup: kill(-6818, 9) failed: No such process
09-28 15:48:44.469  1931  1948 I libprocessgroup: Successfully killed process cgroup uid 10086 pid 6818 in 80ms
shankari commented 4 years ago

Services restarted through periodic check

09-28 16:45:16.782  7605  7630 D TripDiaryStateMachineForegroundService: In checkForegroundNotification, found 0 active notifications
09-28 16:45:16.785  7605  7630 D TripDiaryStateMachineForegroundService: Did not find foreground notification with ID 6646464 in list java.util.stream.ReferencePipeline$3@2be0351
09-28 16:45:16.786  7605  7630 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.Application@95c8ddb
09-28 16:45:16.822  7631  7631 D TripDiaryStateMachineForegroundService: onCreate called
09-28 16:45:16.823  7631  7631 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-28 16:45:16.826  7631  7631 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 16:45:16.867  7631  7631 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@d0c2cb7
09-28 16:45:16.872  7631  7631 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
09-28 16:45:16.873  7631  7631 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service

Upgraded Chrome through Google Play, service NOT terminated. So maybe the Application context is the charm? No, see https://github.com/e-mission/e-mission-docs/issues/580#issuecomment-700340231

shankari commented 4 years ago

so how do we fix this? We cannot rely on any callbacks because they may or may not happen. So we need to work with a mix of optimism and pessimism.

1) Switch back to making the calls directly from the activity since it doesn't really help to move to the broadcast receiver 2) Add code to the periodic check to recreate the foreground service 3) As an optimization, add code to the onDestroy callback to launch the service again. We have to be careful about this because sending a broadcast doesn't actually switch to a different thread or process, and we know that this process is going to terminate ASAP (see the onDestroy logs above, reproduced here). This optimization will lessen the time that we have no foreground notification and ensure that we miss as little data as possible.

09-27 18:47:31.985  1929  1943 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 20848ms
09-27 18:47:52.851  1929  3214 W ActivityManager: Stopping service due to app idle: u0a87 -5m25s546ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 18:47:52.871  1929  1945 I ActivityManager: Start proc 15872:gov.colorado.energyoffice.emission/u0a87 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-27 18:47:53.240 15872 15872 D TripDiaryStateMachineForegroundService: onDestroy called for foreground service
09-27 18:47:53.240 15872 15872 D TripDiaryStateMachineForegroundService: onDestroy called, removing notification

We could try to send the broadcast and see if it works, and then we can figure out whether we need to use a JobScheduler instead.

For now, we will: 4) Send a broadcast notification from onDestroy 5) Generate a user visible notification asking people to send me logs 6) Generate a user visible notification when we are recreating asking people to send me logs

We will test the destroy code by stopping the service using adb https://stackoverflow.com/questions/7415997/how-to-start-and-stop-android-service-from-a-adb-shell

shankari commented 4 years ago

Tried to test the first set of fixes above; service was restarted properly/didn't crash. logcat.didntcrash.log.gz When I re-ran without any modifications, it did crash.

09-28 20:35:40.189  3746  4602 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.Application@954f0b6
09-28 20:35:40.195  3746  3746 D TripDiaryStateMachineForegroundService: onCreate called
09-28 20:35:40.196  3746  3746 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-28 20:35:40.197  3746  3746 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 20:35:41.884  3746  3746 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@6f28a90
09-28 20:35:41.888  3746  3746 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
09-28 20:35:41.890  3746  3746 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
...
09-28 20:36:22.383  1924  1938 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 20:36:23.409  1924  1940 I ActivityManager: Start proc 9524:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 20:36:23.610  9524  9524 D TripDiaryStateMachineForegroundService: onCreate called
09-28 20:36:23.611  9524  9524 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = null flags = 0 and startId = 3
09-28 20:36:23.655  9524  9524 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
shankari commented 4 years ago

Tested kill + Force sync

09-28 22:01:56.572  1933  1947 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
09-28 22:01:57.586  1933  1949 I ActivityManager: Start proc 6322:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-28 22:01:57.604  1933  3311 I ActivityManager:   Force stopping service ServiceRecord{bd57256 u0 gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
09-28 22:02:22.965  6484  6605 D TripDiaryStateMachineForegroundService: In checkForegroundNotification, found 0 active notifications
09-28 22:02:22.968  6484  6484 D TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@aee5fd9
09-28 22:02:22.972  6484  6484 D TripDiaryStateMachineForegroundService: onCreate called
09-28 22:02:22.973  6484  6484 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
09-28 22:02:22.973  6484  6484 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
09-28 22:02:22.975  6484  6605 D TripDiaryStateMachineForegroundService: Did not find foreground notification with ID 6646464 in list []
09-28 22:02:22.991  6484  6605 D TripDiaryStateMachineForegroundService: startProperly called with context = gov.colorado.energyoffice.emission.MainActivity@b871bf8
09-28 22:02:23.019  6484  6484 D TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
09-28 22:02:23.020  6484  6484 D TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
09-28 22:02:23.020  6484  6484 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.start starting foreground service
shankari commented 4 years ago

wrt "4) Send a broadcast notification from onDestroy", I tried to call the startProperly method directly in a separate thread, but the thread is never invoked. I guess the entire process is killed. Need to send a broadcast notification or use a JobScheduler.

Broadcast notification would be easiest, but there are limitations on starting services in the background, and we won't be in the foreground once we are destroyed. So maybe we should use a job scheduler after all?

shankari commented 4 years ago

Since this is an optimization, and we are short of time, going to skip the changes to onDestroy.

shankari commented 4 years ago

next set of checks: how do we deal with kills/restarts while in ongoing_trip mode? Recall that in the original issue, we were in ongoing_trip mode when the app was reinstalled, so we didn't restart the tracking https://github.com/e-mission/e-mission-docs/issues/580#issuecomment-699263281

Do we need to? Let's verify by testing in ongoing_trip mode

shankari commented 4 years ago

7:16: Install app and resolve all alerts 7:17: Start route in emulator 7:18: Move to ongoing_trip

2020-09-29 07:16:06.809 3756-5815/gov.colorado.energyoffice.emission D/GeofenceLocationIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.actions.GeofenceLocationIntentService (has extras) }
2020-09-29 07:16:06.841 3756-5815/gov.colorado.energyoffice.emission D/GeofenceLocationIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.actions.GeofenceLocationIntentService (has extras) }
2020-09-29 07:18:11.746 3756-6151/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 07:18:11.810 3756-6151/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 07:18:15.167 3756-6158/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 07:18:15.186 3756-6159/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 07:18:42.743 3756-6163/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 07:18:46.185 3756-6164/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }

7:19: Kill activity

2020-09-29 07:19:21.099 3756-6185/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 07:19:44.812 3756-6194/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 07:19:48.226 3756-6197/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }

7:20: Upgrade chrome, foreground service killed, updates stop

2020-09-29 07:20:18.241 3756-6211/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 07:20:21.679 3756-6214/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }

7:21: Relaunch activity 7:22: force sync, foreground service returns, no more updates although emulator is receiving updates 7:23: force send initialize, app goes to waiting_for_trip_start

2020-09-29 07:23:27.796 6433-6433/gov.colorado.energyoffice.emission I/TripDiaryStateMachineRcvr: noarg constructor called
2020-09-29 07:23:27.796 6433-6433/gov.colorado.energyoffice.emission I/TripDiaryStateMachineRcvr: TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@c9c5dca, Intent { act=local.transition.initialize flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called
2020-09-29 07:23:27.802 6433-6433/gov.colorado.energyoffice.emission I/TripDiaryStateMachineRcvr: 2016-07-14 is the current consented version, sending msg to service...
2020-09-29 07:23:27.803 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@c9c5dca
2020-09-29 07:23:27.807 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
2020-09-29 07:23:27.808 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.ongoing_trip starting foreground service
2020-09-29 07:23:27.814 6433-6433/gov.colorado.energyoffice.emission I/TripDiaryStateMachineService: Service created. Initializing one-time variables!
2020-09-29 07:23:27.815 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: service started with flags = 0 startId = 1 action = local.transition.initialize
2020-09-29 07:23:27.816 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: after reading from the prefs, the current state is local.state.ongoing_trip
2020-09-29 07:23:27.819 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: handleAction(local.state.ongoing_trip, local.transition.initialize) called
2020-09-29 07:23:27.825 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: TripDiaryStateMachineReceiver handleStarted(local.transition.initialize) called
2020-09-29 07:23:27.826 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: handleAction(local.state.ongoing_trip, local.transition.initialize) completed, waiting for async operations to complete
2020-09-29 07:23:27.829 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
2020-09-29 07:23:27.836 6433-6433/gov.colorado.energyoffice.emission E/ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@5adc22
2020-09-29 07:23:27.897 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: newState after handling action is local.state.waiting_for_trip_start
2020-09-29 07:23:27.907 6433-6433/gov.colorado.energyoffice.emission D/TripDiaryStateMachineService: newState saved in prefManager is local.state.waiting_for_trip_start
2020-09-29 07:23:27.922 6433-6433/gov.colorado.energyoffice.emission I/TripDiaryStateMachineService: Service destroyed. So long, suckers!

This is because we always call handleStart on initialize. This will move us to waiting_for_trip_start. Presumably in the real phone with geofencing working, this would then immediately trigger geofence exit and we would continue tracking.

        if (actionString.equals(ctxt.getString(R.string.transition_initialize))) {
            handleStart(ctxt, actionString);

This is also how phone upgrades or reboots will work. So if we generate an initialize transition as well when we restart the foreground service, we should be done.

We may want to rethink the handling of the initialize transition to make it easier to continue an ongoing trip instead of moving to waiting_for_trip_start and then moving out again. But that is a separate change.

shankari commented 4 years ago

After the fix:

8:21: Install app and resolve all alerts 8:22: Start route in emulator 8:23: Move to ongoing trip

2020-09-29 08:23:39.442 3852-6143/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:23:39.490 3852-6144/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:23:42.852 3852-6149/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 08:23:42.865 3852-6150/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 08:24:10.488 3852-6154/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:24:13.927 3852-6158/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }

8:24: kill activity

2020-09-29 08:24:10.488 3852-6154/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:24:13.927 3852-6158/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 08:24:33.681 3852-6168/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
2020-09-29 08:24:40.526 3852-6172/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:25:11.528 3852-6193/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }

8:25: Upgrade chrome; service killed

2020-09-29 08:25:41.729 1929-1943/? W/ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
2020-09-29 08:25:42.732 1929-3783/? W/ActivityManager: Stopping service due to app idle: u0a86 -5m32s26ms gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
2020-09-29 08:25:42.745 1929-1945/? I/ActivityManager: Start proc 6236:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-29 08:25:42.745  1929  1945 I ActivityManager: Start proc 6236:gov.colorado.energyoffice.emission/u0a86 for service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService
09-29 08:25:42.754  6236  6236 I office.emissio: Not late-enabling -Xcheck:jni (already on)
09-29 08:25:42.777  6236  6236 W office.emissio: Unexpected CPU variant for X86 using defaults: x86
09-29 08:25:42.878  6236  6236 I office.emissio: The ClassLoaderContext is a special shared library.
09-29 08:25:42.948  1929  2784 I ActivityManager: Killing 6236:gov.colorado.energyoffice.emission/u0a86 (adj 0): stop gov.colorado.energyoffice.emission
09-29 08:25:42.948  1929  1946 W libprocessgroup: kill(-6236, 9) failed: No such process
09-29 08:25:42.990  1929  1946 W libprocessgroup: kill(-6236, 9) failed: No such process
09-29 08:25:42.990  1768  1768 I Zygote  : Process 6236 exited due to signal (9)
09-29 08:25:43.029  1929  1946 W libprocessgroup: kill(-6236, 9) failed: No such process
09-29 08:25:43.029  1929  1946 I libprocessgroup: Successfully killed process cgroup uid 10086 pid 6236 in 80ms

8:29: Force sync

2020-09-29 08:29:09.137 6438-6562/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: In checkForegroundNotification, found 0 active notifications
2020-09-29 08:29:09.138 6438-6562/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: Did not find foreground notification with ID 6646464 in list []
2020-09-29 08:29:09.147 6438-6562/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = gov.colorado.energyoffice.emission.MainActivity@2f198bc
2020-09-29 08:29:09.149 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onCreate called
2020-09-29 08:29:09.150 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 1
2020-09-29 08:29:09.151 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.ongoing_trip starting foreground service
2020-09-29 08:29:09.177 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: startProperly called with context = android.app.ReceiverRestrictedContext@65398cd
2020-09-29 08:29:09.180 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called with intent = Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService } flags = 0 and startId = 2
2020-09-29 08:29:09.181 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg In state local.state.ongoing_trip starting foreground service
2020-09-29 08:29:09.197 6438-6438/gov.colorado.energyoffice.emission D/TripDiaryStateMachineForegroundService: onBind called with intent Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService }
2020-09-29 08:29:09.199 6438-6438/gov.colorado.energyoffice.emission E/ForegroundServiceComm: Successfully bound to service edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService@16d55e8
2020-09-29 08:29:09.255 6438-6438/gov.colorado.energyoffice.emission D/ForegroundServiceComm: Service successfully bound, setting state
2020-09-29 08:29:09.267 6438-6438/gov.colorado.energyoffice.emission D/ForegroundServiceComm: Destroying FSM service, unbinding foreground service

8:30: in waiting_for_trip_start. exited geofence

2020-09-29 08:30:55.848 6438-6596/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:30:55.853 6438-6596/gov.colorado.energyoffice.emission D/LocationChangeIntentService: FINALLY! Got location update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) }
2020-09-29 08:30:56.436 6438-6603/gov.colorado.energyoffice.emission D/ActivityRecognitionChangeIntentService: FINALLY! Got activity update, intent is Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }
shankari commented 4 years ago

One final change while we are here.

Let's add a new periodic check where if we are in ongoing_trip and we haven't received entries for a while, we send an initialize. Since we have a time filter here, we should expect to see periodic updates. Since the time filter is configurable, let's pick a time that is 200 the time filter. For our default of 30 secs, this should be `30 200 / 60` = 100 mins = close to 2 hours.

The data for those 2 hours is gone, but at least we can recover somewhat gracefully.