Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Trips do not detect trip end even after stopping #567

Closed
shankari opened this issue Aug 21, 2020 · 35 comments
Closed

Trips do not detect trip end even after stopping #567

shankari opened this issue Aug 21, 2020 · 35 comments

Comments

@shankari
Copy link
Contributor

Reported by Ryan

I had another bike trip that lasted from 8:30 to8:50am and the trip started fine, but did not stop until 10:30 or so.

and Andy

I left at 12:32pm and trip logged as 6 hours duration.

@shankari
Copy link
Contributor Author

Haven't received logs from Ryan yet, but do have logs from Andy. There are basically only sporadic updates to the location during this period, with the large gaps indicated.

13064,1597775577.284,2020-08-18T12:32:57.284000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13077,1597775586.154,2020-08-18T12:33:06.154000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13101,1597775599.187,2020-08-18T12:33:19.187000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13125,1597775641.0970001,2020-08-18T12:34:01.097000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13149,1597775664.274,2020-08-18T12:34:24.274000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13173,1597776276.7779999,2020-08-18T12:44:36.778000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13182,1597776302.1360002,2020-08-18T12:45:02.136000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13206,1597777219.3920002,2020-08-18T13:00:19.392000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13220,1597777219.5270002,2020-08-18T13:00:19.527000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13227,1597777219.544,2020-08-18T13:00:19.544000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13251,1597777589.992,2020-08-18T13:06:29.992000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13275,1597778239.6920002,2020-08-18T13:17:19.692000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13299,1597778882.218,2020-08-18T13:28:02.218000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13323,1597778913.961,2020-08-18T13:28:33.961000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13347,1597779515.772,2020-08-18T13:38:35.772000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13371,1597780143.82,2020-08-18T13:49:03.820000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13395,1597780581.2470002,2020-08-18T13:56:21.247000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13419,1597780602.248,2020-08-18T13:56:42.248000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13448,1597781203.187,2020-08-18T14:06:43.187000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13472,1597781854.5770001,2020-08-18T14:17:34.577000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13496,1597782491.645,2020-08-18T14:28:11.645000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13520,1597783111.283,2020-08-18T14:38:31.283000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13544,1597783572.571,2020-08-18T14:46:12.571000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13568,1597783593.3070002,2020-08-18T14:46:33.307000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13597,1597784219.2870002,2020-08-18T14:56:59.287000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13621,1597784845.853,2020-08-18T15:07:25.853000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13645,1597785520.169,2020-08-18T15:18:40.169000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13669,1597786147.35,2020-08-18T15:29:07.350000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13693,1597786567.356,2020-08-18T15:36:07.356000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13717,1597787174.915,2020-08-18T15:46:14.915000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13741,1597787787.0170002,2020-08-18T15:56:27.017000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
13762,1597787787.2970002,2020-08-18T15:56:27.297000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13791,1597788461.542,2020-08-18T16:07:41.542000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13815,1597789119.4160001,2020-08-18T16:18:39.416000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13839,1597789558.27,2020-08-18T16:25:58.270000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13863,1597790221.0,2020-08-18T16:37:01-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13887,1597790858.438,2020-08-18T16:47:38.438000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13911,1597790934.185,2020-08-18T16:48:54.185000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13946,1597796794.698,2020-08-18T18:26:34.698000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13970,1597797398.842,2020-08-18T18:36:38.842000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

13994,1597798056.825,2020-08-18T18:47:36.825000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

-------> GAP <-------

14018,1597798526.995,2020-08-18T18:55:26.995000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
14042,1597798649.7779999,2020-08-18T18:57:29.778000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
14068,1597798651.529,2020-08-18T18:57:31.529000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
14097,1597798657.343,2020-08-18T18:57:37.343000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
14126,1597798663.063,2020-08-18T18:57:43.063000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
14155,1597798668.0,2020-08-18T18:57:48-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"
14184,1597798673.1179998,2020-08-18T18:57:53.118000-06:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent {  }"

@shankari
Copy link
Contributor Author

shankari commented Aug 23, 2020

This behavior seems to be consistent with the app running in the background, without a foreground service
https://developer.android.com/about/versions/oreo/background-location-limits

In an effort to reduce power consumption, Android 8.0 (API level 26) limits how frequently background apps can retrieve the user's current location. Apps can receive location updates only a few times each hour.

But why is the foreground service workaround not working? Could this be related to #571?

@shankari
Copy link
Contributor Author

This does in fact seem to be related to #571. In the case where the trip doesn't work, we have equal numbers of foreground service start and destroy.

13027,1597775576.965,2020-08-18T12:32:56.965000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
13052,1597775577.164,2020-08-18T12:32:57.164000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
13059,1597775577.262,2020-08-18T12:32:57.262000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
13069,1597775577.331,2020-08-18T12:32:57.331000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
13072,1597775586.121,2020-08-18T12:33:06.121000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
13093,1597775586.2810001,2020-08-18T12:33:06.281000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

But in the case where it did work, we had one extra start

394,1597545734.054,2020-08-15T20:42:14.054000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
410,1597545734.708,2020-08-15T20:42:14.708000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
417,1597545734.76,2020-08-15T20:42:14.760000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
445,1597545734.9420002,2020-08-15T20:42:14.942000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
456,1597545735.0129998,2020-08-15T20:42:15.013000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
459,1597545803.945,2020-08-15T20:43:23.945000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
481,1597545804.482,2020-08-15T20:43:24.482000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

So in the second case, we must have had a persistent foreground service, while in the first case, we would not. It looks like the approach of starting a foreground service for each callback (which was arguably lame in the first place) is no longer working.

@shankari
Copy link
Contributor Author

Wait, if we look at the counts, they are not that different

$ grep ForegroundService.*onStartCommand /tmp/andy.focus_area | wc -l
      62

$ grep ForegroundService.*onDestroy /tmp/andy.focus_area | wc -l
      55

$ grep ForegroundService.*onStartCommand /tmp/andy.worked | wc -l
     177

$ grep ForegroundService.*onDestroy /tmp/andy.worked | wc -l
     171

@shankari
Copy link
Contributor Author

shankari commented Aug 23, 2020

ok, so I don't fully understand what is going on here, but after the initial startup, the start and destroy clearly occur in pairs.

459,1597545803.945,2020-08-15T20:43:23.945000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
481,1597545804.482,2020-08-15T20:43:24.482000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

484,1597545827.611,2020-08-15T20:43:47.611000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
506,1597545829.111,2020-08-15T20:43:49.111000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

And at the beginning, there seems to be one extra start from a location service than a destroy

394,1597545734.054,2020-08-15T20:42:14.054000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
393,1597545734.05,2020-08-15T20:42:14.050000-06:00,TripDiaryStateMachineService : service started with flags = 0 startId = 1 action = local.transition.exited_geofence
409,1597545734.518,2020-08-15T20:42:14.518000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 1
410,1597545734.708,2020-08-15T20:42:14.708000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
415,1597545734.7410002,2020-08-15T20:42:14.741000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 2
417,1597545734.76,2020-08-15T20:42:14.760000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
443,1597545734.928,2020-08-15T20:42:14.928000-06:00,"TripDiaryStateMachineService : Service destroyed. So long, suckers!"
445,1597545734.9420002,2020-08-15T20:42:14.942000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
455,1597545735.002,2020-08-15T20:42:15.002000-06:00,LocationChangeIntentService : onDestroy called
456,1597545735.0129998,2020-08-15T20:42:15.013000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

@shankari
Copy link
Contributor Author

Ah there was indeed a re-entrant start, and a single destroy

409,1597545734.518,2020-08-15T20:42:14.518000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 1
415,1597545734.7410002,2020-08-15T20:42:14.741000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 2
455,1597545735.002,2020-08-15T20:42:15.002000-06:00,LocationChangeIntentService : onDestroy called

@shankari
Copy link
Contributor Author

But we see the same behavior in the failure case, although it happens much after the tracking. In fact, there are 3 starts. Why don't we see the same frequent updates in that case?

13200,1597777218.591,2020-08-18T13:00:18.591000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 1
13201,1597777218.721,2020-08-18T13:00:18.721000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
13207,1597777219.393,2020-08-18T13:00:19.393000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 2
13208,1597777219.4029999,2020-08-18T13:00:19.403000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
13215,1597777219.505,2020-08-18T13:00:19.505000-06:00,LocationChangeIntentService : onStart called with Intent { cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 3
13216,1597777219.514,2020-08-18T13:00:19.514000-06:00,LocationChangeIntentService : availability = false
13217,1597777219.519,2020-08-18T13:00:19.519000-06:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
13226,1597777219.535,2020-08-18T13:00:19.535000-06:00,LocationChangeIntentService : availability = true
13242,1597777219.615,2020-08-18T13:00:19.615000-06:00,LocationChangeIntentService : onDestroy called
13243,1597777219.617,2020-08-18T13:00:19.617000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

@shankari
Copy link
Contributor Author

Why don't we see the same frequent updates in that case?

Not sure. But we are going to change this anyway, so let's try to change to a single, persistent foreground service and see if that fixes the problem.

@shankari
Copy link
Contributor Author

What we do now is to start an intermittent foreground service every time we want to do anything in the background. This has us starting not just IntentServices every 30 secs, but also the ForegroundService. Which is clearly terrible. We want to replace it with a longer-lived service.

So there are two ways in which we can start a longer-lived foreground service:

  1. We start the service when the tracking stop and stop it when the tracking stops
  2. We start the service when the user consents, keep it running all the time, and have it reflect the current status of the FSM

The second option seems more robust since we will always have the foreground service running and will avoid missing foreground issues like the ones in this bug. In Android 11 (API 30, there are also going to be additional restrictions on foreground services although we do have the ACCESS_BACKGROUND_LOCATION permission, so maybe this is not a huge deal.

Let's try the second option and switch to the first option only if we need to.

@shankari
Copy link
Contributor Author

Hm, android doesn't like us to use foreground services for passive location tracking.
https://android-developers.googleblog.com/2018/12/effective-foreground-services-on-android_11.html

But we can't get frequent updates unless we do. Maybe we should try the first option first though.

@shankari
Copy link
Contributor Author

Couple of background notes before we start the refactor:

  • Although TripDiaryStateMachineForegroundService is currently a service, it is rarely invoked as one.
$ grep "TripDiaryStateMachineForegroundService.*called with flags" /tmp/loggerDB.j.controlling_fsm.withdate.log | wc -l
       5

Instead, we call the handleStart call most of the time. Note that this doesn't start a new service, but promotes the incoming service to foreground.

$ grep "TripDiaryStateMachineForegroundService.*oreo+" /tmp/loggerDB.j.controlling_fsm.withdate.log | wc -l
     345

We started this foreground pattern because without it, background services don't start

03-18 15:19:47.684  5308  5308 I LocationSettingsBase: Location mode has been changed
03-18 15:19:47.687  1670  2272 W ActivityManager: Background start not allowed: service Intent { cmp=edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.GeofenceExitIntentService (has extras) } to edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.GeofenceExitIntentService from pid=-1 uid=10091 pkg=edu.berkeley.eecs.embase

Due to restrictions on

Background Service Limitations: While an app is idle, there are limits to its use of background services. This does not apply to foreground services, which are more noticeable to the user.

on background apps launching background services

If your app needs to create a foreground service while the app is in the background, use the startForegroundService() method instead of startService().

Note: IntentService is a service, and is therefore subject to the new restrictions on background services. As a result, many apps that rely on IntentService do not work properly when targeting Android 8.0 or higher. For this reason, Android Support Library 26.0.0 introduces a new JobIntentService class, which provides the same functionality as IntentService but uses jobs instead of services when running on Android 8.0 or higher.

Prior to Android 8.0, the usual way to create a foreground service was to create a background service, then promote that service to the foreground. With Android 8.0, there is a complication; the system doesn't allow a background app to create a background service. For this reason, Android 8.0 introduces the new method startForegroundService() to start a new service in the foreground. After the system has created the service, the app has five seconds to call the service's startForeground() method to show the new service's user-visible notification. If the app does not call startForeground() within the time limit, the system stops the service and declares the app to be ANR.

@shankari
Copy link
Contributor Author

As a quick check on where this was called before, in at least one case, it was due to a restart in the ongoing state

2665,1596999432.681,2020-08-09T11:57:12.681000-07:00,UnifiedLogger : finished init of android native code
2666,1596999432.684,2020-08-09T11:57:12.684000-07:00,truncating obsolete entries before 1.594407432684E9
2667,1596999432.704,2020-08-09T11:57:12.704000-07:00,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.596999432701E9
2668,1596999432.708,2020-08-09T11:57:12.708000-07:00,TripDiaryStateMachineRcvr : Comparing installed version 1 with new version 1
2669,1596999432.71,2020-08-09T11:57:12.710000-07:00,"TripDiaryStateMachineRcvr : Setup complete, skipping initialize"
2670,1596999432.711,2020-08-09T11:57:12.711000-07:00,TripDiaryStateMachineRcvr : checking to see whether to start foreground service
2671,1596999432.7129998,2020-08-09T11:57:12.713000-07:00,"TripDiaryStateMachineRcvr : app restarted while in the ongoing state, starting foreground service ASAP"
2672,1596999432.835,2020-08-09T11:57:12.835000-07:00,TripDiaryStateMachineForegroundService : onStartCommand called with flags = 0 and startId = 1
2673,1596999432.839,2020-08-09T11:57:12.839000-07:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"

@shankari
Copy link
Contributor Author

shankari commented Aug 24, 2020

In the other cases, it seems like we do call if from handleTripStart, handleTripEnd and stopAll.

So the current service lifecycles are:

  • on geofence exit: create the geofence service as a foreground service
  • this generates a broadcast which is received by the Broadcast Receiver
  • destroy the geofence service
  • the Broadcast Receiver then calls handleStart, which creates the TripDiaryStateMachineForegroundService
  • every location update then creates the location intent as a foreground service (why do we need this when we already have a foreground service?)
  • every location update destroys the location foreground service
  • on handleTripEnd, we destroy the TripDiaryStateMachineForegroundService

@shankari
Copy link
Contributor Author

shankari commented Aug 24, 2020

Right now, we have the foreground service started from the FSM. This is very principled, but incorrect, because we need to perform some operations before the FSM is launched, at the start of the trip. One option is to launch the foreground service first and use it to launch the GeofenceService.

In this case, the service lifecycle would be:

  • when the user consents, start the foreground service
  • start all the other services in the background as usual since there will be a foreground service associated with the app
  • when the geofence exits, start the foreground service and use it to turn on the geofence
  • when we return to waiting_for_trip_start, stop the foreground service

@shankari
Copy link
Contributor Author

I think we can also make an argument for Option 1 since we are tracking the location, albeit passively. And we can set it up so that users can click the ongoing service notification to start and stop trips manually, which would be useful, right?

@shankari
Copy link
Contributor Author

Let's check with some users and make a decision.

@shankari
Copy link
Contributor Author

shankari commented Aug 24, 2020

For the record, the lifecycle for option 1 would be:

  • when the user consents, start the foreground service
  • when the app reboots (e.g. on all INITIALIZE calls, start the foreground service). In the future, we change the boot receiver to generate a notification other than INITIALIZE, we can fine-tune this further.
  • start all other services in the background as usual
  • when the user turns tracking off, stop the foreground service
  • when the user turns tracking on, start the foreground service

Everything else works as usual. Expose a service interface and allow the FSM to bind to it for status updates and icon changes.

@shankari
Copy link
Contributor Author

shankari commented Aug 24, 2020

Instant feedback from users:

  • M: won't care
  • J: dislikes notification, would prefer that it not exist, but can live with it
  • R: bit annoying, but can ignore it. Would prefer more meaningful message.

So going to start with Option 1 given time budget. Once we have a long-lived service working reliably, should be possible to shorten its duration later.

@shankari
Copy link
Contributor Author

Final question: how do we send message updates to the service so that it shows something meaningful? We could restart it multiple times with multiple intents, but that seems a bit lame. Instead, we can expose a binding (e.g. setMessage) and call that from the FSM code. It looks like the combination of startService and bindings should work well. If the service was explicitly started, then it will only be stopped when we explicitly stop it. Otherwise it will be in unbound but running state.

https://stackoverflow.com/questions/3514287/android-service-startservice-and-bindservice

@shankari
Copy link
Contributor Author

To simplify this, and only show the foreground service when we are actively tracking, we can use a BroadcastReceiver for the PendingIntent instead of the IntentService. This makes the code much nicer because we can start and end the foreground service from the receiver or the FSM, which is more principled.
https://developer.android.com/training/location/geofencing

    private PendingIntent getGeofencePendingIntent() {
        // Reuse the PendingIntent if we already have it.
        if (geofencePendingIntent != null) {
            return geofencePendingIntent;
        }
        Intent intent = new Intent(this, GeofenceBroadcastReceiver.class);
        // We use FLAG_UPDATE_CURRENT so that we get the same pending intent back when
        // calling addGeofences() and removeGeofences().
        geofencePendingIntent = PendingIntent.getBroadcast(this, 0, intent, PendingIntent.
                FLAG_UPDATE_CURRENT);
        return geofencePendingIntent;
    }

@shankari
Copy link
Contributor Author

Turns out that even if we turn the service off as part of "Stop tracking", we restart it as part of the re-binding in setNewState. Need to figure out how to clean that up later. For now, just removing the code to turn the service off and on. It will just remain on all the time.

@shankari
Copy link
Contributor Author

Cleaned up the code around binding a bit so that we bind on create and unbind on destroy. This ensures that we don't restart the service all the time, and fixes the issue where the state is not reflected properly. One question that I still have with the debugging is why the initialize transition is called twice.

Let's spend a really short time to review.

@shankari
Copy link
Contributor Author

Ok, this is why:
We receive a start_tracking event when we are in the tracking_stopped state, which generates one initialize and moves to the startState.

    private void handleTrackingStopped(final Context ctxt, String actionString) {
        Log.d(this, TAG, "TripDiaryStateMachineReceiver handleTrackingStopped(" + actionString + ") called");
        if (actionString.equals(ctxt.getString(R.string.transition_start_tracking))) {
            ctxt.sendBroadcast(new ExplicitIntent(ctxt, R.string.transition_initialize));
            setNewState(ctxt.getString(R.string.state_start), true);
            return;
            // createGeofenceInThread(ctxt, apiClient, actionString);

and then as part of setting the new state, we check the permissions and settings, which resets the FSM in start state

    public static void restartFSMIfStartState(Context ctxt) {
        String START_STATE = ctxt.getString(R.string.state_start);
        String currState = getState(ctxt);
        Log.i(ctxt, TAG, "in restartFSMIfStartState, currState = "+currState);
        if (START_STATE.equals(currState)) {
            Log.i(ctxt, TAG, "in start state, sending initialize");
            ctxt.sendBroadcast(new ExplicitIntent(ctxt, R.string.transition_initialize));
        }
    }

We can't fix that without changing the meaning of initialize in the FSM, and I don't plan to right now. start/stop tracking is not a common use case anyway.

@shankari
Copy link
Contributor Author

Tested downgrading location permissions. This crashes the service, and does not launch the geofence service to generate a tracking error.

08-25 12:17:43.535  2047 12703 I ActivityTaskManager: START u0 {act=android.intent.action.MANAGE_APP_PERMISSION cmp=com.google.android.permissioncontroller/com.android.packageinstaller.permission.ui.AppPermissionActivity (has extras)} from uid 10061
...
08-25 12:17:45.024  2047  5779 I ActivityManager: Killing 29765:gov.colorado.energyoffice.emission/u0a136 (adj 50): permissions revoked
08-25 12:17:45.028  2047  5779 W ActivityManager: Scheduling restart of crashed service gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService in 1000ms
...
08-25 12:17:46.042  1782  1782 D Zygote  : Forked child process 10040
08-25 12:17:46.045  2047  2079 I ActivityManager: Start proc 10040:gov.colorado.energyoffice.emission/u0a136 for service {gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineForegroundService}
...
08-25 12:17:46.312 10040 10040 D TripDiaryStateMachineForegroundService: onStartCommand called with flags = 0 and startId = 11
08-25 12:17:46.326 10040 10040 D TripDiaryStateMachineForegroundService: onStartCommand called on oreo+, with msg background trip tracking started starting foreground service

If we can detect that the ForegroundService was restarted before killing, that would be good. Otherwise, we may need to switch to a foreground service for the geofence anyway so we can get the tracking error.

@shankari
Copy link
Contributor Author

Detected using intent which is null on restart.

@shankari
Copy link
Contributor Author

shankari commented Aug 25, 2020

Turning off location services completely doesn't do anything automatically. In particular, I don't seem to get a tracking_error in the GeofenceExitIntentService. Tried on both v0.0.1 of CoBike and on the old emTripLog. Turned off the location tracking at around 1:19 - 1:20pm on both of them; let's see when we next get a notification.

@shankari
Copy link
Contributor Author

We are definitely not getting a GeofenceIntent with error on the two prior versions of the app. So maybe this is OK after all?
But when I look at Stan's logs from #566 then I do see the GeofenceExit intent with the error. But I don't on J's phone although they have the same version.

173,1597428818.8070002,2020-08-14T11:13:38.807000-07:00,GeofenceExitIntentService : onCreate called
174,1597428818.899,2020-08-14T11:13:38.899000-07:00,GeofenceExitIntentService : onStartCommand called with intent Intent { } flags 0 startId 1
175,1597428818.926,2020-08-14T11:13:38.926000-07:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, starting foreground service"
179,1597428819.039,2020-08-14T11:13:39.039000-07:00,GeofenceExitIntentService : onStart called with startId 1
180,1597428819.07,2020-08-14T11:13:39.070000-07:00,GeofenceExitIntentService : geofence exit intent action = null
181,1597428819.093,2020-08-14T11:13:39.093000-07:00,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@c1803c8
182,1597428819.1139998,2020-08-14T11:13:39.114000-07:00,GeofenceExitIntentService : got geofence intent callback with type -1 and location null
183,1597428819.13,2020-08-14T11:13:39.130000-07:00,GeofenceExitIntentService : Found error 1000 generating tracking error
184,1597428819.2229998,2020-08-14T11:13:39.223000-07:00,GeofenceExitIntentService : onDestroy called
185,1597428819.2370002,2020-08-14T11:13:39.237000-07:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

@shankari
Copy link
Contributor Author

Turned off on M's phone at 1:52pm.

@shankari
Copy link
Contributor Author

And this is not a background v/s foreground issue because

./adb logcat | grep "Background start not allowed"
   <multiple instances of >
08-25 12:35:27.404  2047  7886 W ActivityManager: Background start not allowed: service Intent { cmp=com.google.android.apps.messaging/.shared.datamodel.action.execution.ActionExecutorImpl$EmptyService } to com.google.android.apps.messaging/.shared.datamodel.action.execution.ActionExecutorImpl$EmptyService from pid=18627 uid=10121 pkg=com.google.android.apps.messaging startFg?=false

@shankari
Copy link
Contributor Author

shankari commented Aug 25, 2020

At any rate, this is not a regression from v0.0.1, so let's go on. Still not quite sure how/why this worked on Stan's phone but not even on the older version of emTripLog. I wonder if I can file an issue against GooglePlayServices for this code.

@shankari
Copy link
Contributor Author

Retesting on emTripLog: everything valid at 2:18.
Turning off location at 2:21 - does nothing.

@shankari
Copy link
Contributor Author

shankari commented Aug 25, 2020

However, testing on a slightly older version of android (with the same APK) does work.
Here are the testing results, which I will also copy/paste into a new bug:

  • API 29 (Android 10, play services: 17.7.86): no effect on app. But when location services is turned on again, we get a geofence exit.
  • API 28 (Android 9, play services: 16.0.89): starts with google location services off. Prompt to turn them on. Turning off gets notification + move to start state.
  • API 27 (Android 8.1.0, play services: 20.30.19): starts with google location services off. Prompts to turn them on. Turning off has no effect.
  • API 26 (Android 8.0): starts with google location services off. Prompt to turn them on. Turning off has no effect.

@shankari
Copy link
Contributor Author

There might be a race when we are in the start state, we get an initialize, and we are not able to create a geofence (for whatever reason). Need to experiment further.

infinite_loop.logs.gz

@shankari
Copy link
Contributor Author

I can sort of reproduce this by:

  • wiping the emulator data,
  • turning off location,
  • going through the normal onboarding process,
  • seeing an location 6 error
  • clicking on it (nothing happens)
  • clicking on it again, everything works

Once we have automated tests, we should have some codemonkey stuff around this to see if we can reproduce.

@shankari
Copy link
Contributor Author

This seems to be the bug for weird FSM issues.

And here's a new one.

Ryan turned his tracking off

155674,1598388679.46,2020-08-25T14:51:19.460000-06:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@3bb94bf, Intent { act=local.transition.stop_tracking flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
155690,1598388679.714,2020-08-25T14:51:19.714000-06:00,TripDiaryStateMachineService : newState after handling action is local.state.tracking_stopped
155701,1598388679.7870002,2020-08-25T14:51:19.787000-06:00,"TripDiaryStateMachineService : All settings are valid, checking current state"
155704,1598388679.801,2020-08-25T14:51:19.801000-06:00,"TripDiaryStateMachineService : in restartFSMIfStartState, currState = local.state.tracking_stopped"

And then the app got updated, which generated an initialize. The initialize transition generated a tracking error, and then we got stuck in an infinite loop of tracking errors.

155851,1598460181.3820002,2020-08-26T10:43:01.382000-06:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@5e5732b, 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"
155853,1598460181.4120002,2020-08-26T10:43:01.412000-06:00,TripDiaryStateMachineService : service started with flags = 0 startId = 1 action = local.transition.tracking_error
155854,1598460181.418,2020-08-26T10:43:01.418000-06:00,"TripDiaryStateMachineService : after reading from the prefs, the current state is local.state.tracking_stopped"
155856,1598460181.439,2020-08-26T10:43:01.439000-06:00,"TripDiaryStateMachineService : handleAction(local.state.tracking_stopped, local.transition.tracking_error) called"
155877,1598460182.248,2020-08-26T10:43:02.248000-06:00,"NotificationHelper : Generating notify with id 362253737, message Location permission off, click to enable and pending intent PendingIntent{483e30b: android.os.BinderProxy@d735e8}"

If we are in tracking_stopped, we don't care about tracking errors since we are not supposed to be tracking anyway.

shankari added a commit to shankari/e-mission-data-collection that referenced this issue Oct 26, 2020
If we are stopping all the location tracking anyway, then do we care if there
are problems with the location?

No, we don't. Because if we do, we run into an infinite loop if we are in the
tracking_stopped state and we turn location services off. Note that this is a
perfectly valid case which should not generate an error.

But because we recheck, we generate a tracking error, which tries to get us to
stop everything, which then rechecks and generates a tracking error.... ad
infinitum.
e-mission/e-mission-docs#567 (comment)
@shankari shankari closed this as completed Jun 3, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

1 participant