Tracking mysteriously turned off on android

[shankari]

I checked that tracking was on, and the FSM was in waiting_for_trip_start state, but there were no trips for the past several days.

[shankari]

Ok so the logs bear this out - this was reported on the 30th, and the last
geofence exit was on the 25th

30272,1498418179.9,2017-06-25 12:16:19.903000-07:53,"GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused <redacted> acc=21 et=+17h19m3s582ms]"

[shankari]

Let's see what happened after that notification...

30273,1498418179.92,2017-06-25 12:16:19.916000-07:53,GeofenceExitIntentService : Geofence exited! Intent = Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService launchParam=MultiScreenLaunchParams { mDisplayId=0 mFlags=0 } (has extras) } Starting ongoing monitoring...
30274,1498418179.95,2017-06-25 12:16:19.949000-07:53,BuiltinUserCache : Added value for key background/location at time 1.498418179935E9

No further updates. Next line is from the sync that occurred ~ 45 minutes later.

30275,1498420625.44,2017-06-25 12:57:05.437000-07:53,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.498420625425E9

And everything after that is syncs.

I wonder if this is the issue with location services turned off.

I am going to experiment with that and see if it has the same behavior...

[shankari]

Actually, that might not be it. This looks closer to
#127 (comment)
in that there is no error with the tracking, but it just mysteriously stops.

30272,1498418179.9,2017-06-25 12:16:19.903000-07:53,"GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused <redacted> acc=21 et=+17h19m3s582ms]"
30273,1498418179.92,2017-06-25 12:16:19.916000-07:53,GeofenceExitIntentService : Geofence exited! Intent = Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService launchParam=MultiScreenLaunchParams { mDisplayId=0 mFlags=0 } (has extras) } Starting ongoing monitoring...
30274,1498418179.95,2017-06-25 12:16:19.949000-07:53,BuiltinUserCache : Added value for key background/location at time 1.498418179935E9
30275,1498420625.44,2017-06-25 12:57:05.437000-07:53,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.498420625425E9

Note that the event is apparently never delivered to the TripDiaryStateMachine so the state must be waiting_for_trip_start, which is consistent with what I saw in the UI.

Maybe the solution of recreating the geofence on every sync is the only real solution to avoid such weirdnesses.

[shankari]

I'm beginning to think that this may be an issue with the geofence intent service being killed improperly. Look at the logs above - we get a bunch of messages from the GeofenceExitIntentService, and then we expect to send a broadcast, which is received by the TripDiaryStateMachineReceiver.

There is no code between the usercache and the broadcast.

            Log.d(this, TAG, "Geofence exited! Intent = "+ intent+" Starting ongoing monitoring...");
            // Add the exit location to the tracking database
            UserCacheFactory.getUserCache(this).putSensorData(R.string.key_usercache_location,
                    new SimpleLocation(parsedEvent.getTriggeringLocation()));
            // DataUtils.addPoint(this, parsedEvent.getTriggeringLocation());
            // Let's just re-use the same event for the broadcast, since it has the location information
            // in case we need it on the other side.
            // intent.setAction(getString(R.string.transition_exited_geofence));
            // sendBroadcast(intent);
            sendBroadcast(new Intent(getString(R.string.transition_exited_geofence)));

And we log in the first statement of the broadcast receiver.

    public void onReceive(Context context, Intent intent) {
        Log.i(context, TAG, "TripDiaryStateMachineReciever onReceive(" + context + ", " + intent + ") called");

We know that the usercache was invoked. So either:

1. we sent the broadcast and it was never delivered, or
2. the service was killed/crashed after saving the entry but before sending the broadcast.

we don't yet have data for Jun 25 on google play, but there have been no crashes from Jun 9 to Jun 16, so it seems a bit unlikely.

Also, the behavior observed in #127 (comment) is more consistent with a killed service. Again, the log statements stop while executing innocuous statements, and there is nothing between the statement that was executed and the statement that was not.

        Log.d(this, TAG, "geofence exit intent action = "+intent.getAction());
        GeofencingEvent parsedEvent = GeofencingEvent.fromIntent(intent);
        Log.d(this, TAG, "parsedEvent = "+parsedEvent);
        Log.d(this, TAG, "got geofence intent callback with type "+parsedEvent.getGeofenceTransition()+
            " and location "+parsedEvent.getTriggeringLocation());

And further, the statements now have nothing to do with the broadcast - they stop while parsing the event.

If the service was getting mysteriously stopped for some reason, it would be able to explain both instances, so it seems a bit more likely. I will ask for android logs too if I can get them, but probably not.

I don't see any code on how an IntentService could be stopped, but I can listen to memory pressure events such as onLowMemory() to see if they are called, and also listen to onDestroy() to see if the process is killed as opposed to just stopped.