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

Dealing gracefully with location services toggle #127

Closed
shankari opened this issue Sep 9, 2016 · 82 comments · Fixed by e-mission/e-mission-base#14
Closed

Dealing gracefully with location services toggle #127

shankari opened this issue Sep 9, 2016 · 82 comments · Fixed by e-mission/e-mission-base#14

Comments

@shankari
Copy link
Contributor

shankari commented Sep 9, 2016

Found this while investigating weird behavior on the server side.

Details. Will upload client log soon.

Why are my trips on the 30th and the 2nd smushed together?

Raw trips are already smushed.

2016-09-09 11:40:48,683:DEBUG:Considering trip 57d2ff6af6858fba8c1fea15: 2016-08-30T12:41:01.527000-07:00 -> 2016-08-30T13:04:47.175000-07:00 
2016-09-09 11:40:48,683:DEBUG:Considering trip 57d2ff6af6858fba8c1fea17: 2016-09-02T08:32:56.484000-07:00 -> 2016-09-02T08:48:00.199000-07:00 

We apparently have no data from the 30th to the 2nd

2016-09-09 11:27:08,188:DEBUG:------------------------------2016-08-30T13:05:53.853000-07:00------------------------------
2016-09-09 11:27:08,207:DEBUG:last5MinsDistances.max() = 108.718208965, last10PointsDistance.max() = 91.0129013077
2016-09-09 11:27:08,208:DEBUG:------------------------------2016-09-02T08:32:56.484000-07:00------------------------------
2016-09-09 11:27:08,216:INFO:Found trip end at 2016-08-30T13:04:47.175000-07:00
2016-09-09 11:27:08,216:DEBUG:Setting new trip start point AttrDict({u'local_dt_hour': 8, u'local_dt_timezone': u'America/Los_Angeles', u'local_dt_second': 56, u'local_dt_year': 2016, u'local_dt_month': 9, u'local_dt_weekday': 4, u'elapsedRealtimeNanos': 521505894000000.0, u'loc': {u'type': u'Point', u'coordinates': [-122.2658647, 37.8704782]}, 'user_id': UUID('0763de67-f61e-3f5d-90e7-518e69793954'), u'altitude': 0.0, u'ts': 1472830376.484, u'latitude': 37.8704782, u'sensed_speed': 0.0, u'accuracy': 37.5, u'fmt_time': u'2016-09-02T08:32:56.484000-07:00', u'local_dt_minute': 32, 'metadata_write_ts': 1472830389.521, 'idx': 101616, u'longitude': -122.2658647, u'filter': u'time', '_id': ObjectId('57c9bd830a3eb8b1300cc856'), u'heading': 0, u'local_dt_day': 2}) with idx 101616

We really don't.

>>> locs_df = estb.BuiltinTimeSeries.to_data_df("background/filtered_location", edb.get_timeseries_db().find({'$or': [{'metadata.key': 'background/filtered_location'}], 'user_id': UUID('0763de67-f61e-3f5d-90e7-518e69793954'), 'data.ts': {'$lte': 1472830376.484, '$gte': 1472587487.175}}))
>>> locs_df.sort("ts")[["fmt_time", "ts", "latitude", "longitude"]]

    fmt_time    ts  latitude    longitude
5   2016-08-30T13:04:47.175000-07:00    1472587487.175000   37.870406   -122.267831
4   2016-08-30T13:04:57-07:00   1472587497.000000   37.870552   -122.267727
3   2016-08-30T13:05:18.984000-07:00    1472587518.984000   37.870288   -122.267833
2   2016-08-30T13:05:34-07:00   1472587534.000000   37.870389   -122.268087
1   2016-08-30T13:05:53.853000-07:00    1472587553.853000   37.870132   -122.268087
0   2016-09-02T08:32:56.484000-07:00    1472830376.484000   37.870478   -122.265865

Not even unfiltered locations

>>> locs_df = estb.BuiltinTimeSeries.to_data_df("background/location", edb.get_timeseries_db().find({'$or': [{'metadata.key': 'background/location'}], 'user_id': UUID('0763de67-f61e-3f5d-90e7-518e69793954'), 'data.ts': {'$lte': 1472830376.484, '$gte': 1472587487.175}}))
>>> locs_df.sort("ts")[["fmt_time", "ts", "latitude", "longitude"]]
    fmt_time    ts  latitude    longitude
6   2016-08-30T13:04:47.175000-07:00    1472587487.175000   37.870406   -122.267831
5   2016-08-30T13:04:57-07:00   1472587497.000000   37.870552   -122.267727
4   2016-08-30T13:05:18.984000-07:00    1472587518.984000   37.870288   -122.267833
3   2016-08-30T13:05:34-07:00   1472587534.000000   37.870389   -122.268087
2   2016-08-30T13:05:53.853000-07:00    1472587553.853000   37.870132   -122.268087
0   2016-09-02T08:32:56.484000-07:00    1472830376.484000   37.870478   -122.265865
1   2016-09-02T08:32:56.484000-07:00    1472830376.484000   37.870478   -122.265865

Looking at all data, we see so it looks like the phone was up and we were recording battery information, but we just did not record any data after STOPPED_MOVING transition at shattuck until magically started getting points around the same location again. How did we even start tracking again without an EXITED_GEOFENCE transition?

for doc in edb.get_timeseries_db().find({'user_id': UUID('0763de67-f61e-3f5d-90e7-518e69793954'), 'data.ts': {'$lte': 1472830376.484, '$gte': 1472587487.175}}).sort("data.ts"):
    e = ecwe.Entry(doc)
    print e.get_id(), e.metadata.key, e.data.fmt_time

57c5eda90a3eb8b1300ac2d8 background/filtered_location 2016-08-30T13:04:47.175000-07:00
57c5eda90a3eb8b1300ac2d7 background/location 2016-08-30T13:04:47.175000-07:00
57c5eda90a3eb8b1300ac2d9 background/motion_activity 2016-08-30T13:04:53.212000-07:00
57c5eda90a3eb8b1300ac2db background/filtered_location 2016-08-30T13:04:57-07:00
57c5eda90a3eb8b1300ac2da background/location 2016-08-30T13:04:57-07:00
57c5eda90a3eb8b1300ac2dd background/filtered_location 2016-08-30T13:05:18.984000-07:00
57c5eda90a3eb8b1300ac2dc background/location 2016-08-30T13:05:18.984000-07:00
57c5eda90a3eb8b1300ac2e0 background/filtered_location 2016-08-30T13:05:34-07:00
57c5eda90a3eb8b1300ac2de background/location 2016-08-30T13:05:34-07:00
57c5eda90a3eb8b1300ac2df background/motion_activity 2016-08-30T13:05:38.173000-07:00
57c5eda90a3eb8b1300ac2e2 background/filtered_location 2016-08-30T13:05:53.853000-07:00
57c5eda90a3eb8b1300ac2e1 background/location 2016-08-30T13:05:53.853000-07:00
57c5eda90a3eb8b1300ac2e3 statemachine/transition 2016-08-30T13:05:58.713000-07:00
57c9bd830a3eb8b1300cc818 background/battery 2016-08-30T13:34:25.182000-07:00
57c9bd830a3eb8b1300cc819 background/battery 2016-08-30T14:44:27.462000-07:00
57c9bd830a3eb8b1300cc81a background/battery 2016-08-30T15:44:18.994000-07:00
...
57c9bd830a3eb8b1300cc850 background/battery 2016-09-02T06:46:02.264000-07:00
57c9bd830a3eb8b1300cc851 background/battery 2016-09-02T07:55:15.948000-07:00
57c9bd830a3eb8b1300cc856 background/filtered_location 2016-09-02T08:32:56.484000-07:00
57c9bd830a3eb8b1300cc855 background/location 2016-09-02T08:32:56.484000-07:00
57c9bd830a3eb8b1300cc852 background/location 2016-09-02T08:32:56.484000-07:00

No other transitions in that entire period

>>> locs_df = estb.BuiltinTimeSeries.to_data_df("statemachine/transition", edb.get_timeseries_db().find({'$or': [{'metadata.key': 'statemachine/transition'}], 'user_id': UUID('0763de67-f61e-3f5d-90e7-518e69793954'), 'data.ts': {'$lte': 1472830376.484, '$gte': 1472587487.175}}))
locs_df[["fmt_time", "curr_state", "transition"]]

DEBUG:root:Found 1 results
DEBUG:root:After de-duping, converted 1 points to 1 

    fmt_time    curr_state  transition
0   2016-08-30T13:05:58.713000-07:00    2   2
@shankari
Copy link
Contributor Author

shankari commented Sep 9, 2016

This is legit server behavior. Need to investigate the client.

@shankari
Copy link
Contributor Author

This is because we got a geofence exit at 14:02, but it was null!

161759,1472587740.41,2016-08-30 14:02:00.412000-07:00,GeofenceExitIntentService : onCreat
e called
161760,1472587740.58,2016-08-30 14:02:00.581000-07:00,GeofenceExitIntentService : onStart
Command called with intent Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.locat
ion.GeofenceExitIntentService (has extras) } flags 0 startId 1
161761,1472587740.79,2016-08-30 14:02:00.790000-07:00,GeofenceExitIntentService : onStart
 called with startId 1
161762,1472587740.94,2016-08-30 14:02:00.937000-07:00,GeofenceExitIntentService : geofenc
e exit intent action = null
...
161763,1472589215.47,2016-08-30 14:26:35.472000-07:00,ServerSyncAdapter : Starting sync w
ith push
161764,1472589219.34,2016-08-30 14:26:39.342000-07:00,"BuiltinUserCache : While searching
 for regex of last transition, got 1 results"
161765,1472589219.49,2016-08-30 14:26:39.490000-07:00,"BuiltinUserCache : 1.472587558713E
9: {""currState"":""local.state.ongoing_trip"",""transition"":""local.transition.stopped_
moving""}"

and then at 9:30, we got something similar

163268,1472830382.42,2016-09-02 09:26:02.421000-07:00,GeofenceExitIntentService : onCreate called
163269,1472830382.61,2016-09-02 09:26:02.612000-07:00,GeofenceExitIntentService : onStartCommand called with intent Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService (has extras) } flags 0 startId 1
163270,1472830382.68,2016-09-02 09:26:02.678000-07:00,GeofenceExitIntentService : onStart called with startId 1
163271,1472830382.76,2016-09-02 09:26:02.759000-07:00,GeofenceExitIntentService : geofence exit intent action = null
163272,1472830382.96,2016-09-02 09:26:02.959000-07:00,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@42918898
163273,1472830383.01,2016-09-02 09:26:03.006000-07:00,"GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused 37.870478,-122.265865 acc=38 et=+6d0h51m45s894ms]"
163274,1472830383.04,2016-09-02 09:26:03.039000-07:00,GeofenceExitIntentService : Geofence exited! Intent = Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService (has extras) } Starting ongoing monitoring...
163275,1472830383.22,2016-09-02 09:26:03.221000-07:00,BuiltinUserCache : Added value for key background/location at time 1.472830383088E9

and continued tracking.

It looks like we got intent action = null the second time as well, but
successfully started tracking. What happens between the two?

Here's the relevant code.

        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());

This is really bizarre. There's literally nothing between the two log statements other than parsing the event. Was the event malformed? Was the app terminated? The app is not supposed to be terminated because it is in a service. I guess it could be that the event was malformed.

The one thing that I do know is that it can't be the usercache because we don't access it between those two log lines. Although I guess another option could be that the we did get to the usercache but the logs were lost because they weren't committed.

I wish I had system logs from that time, but alas no chance.

@shankari
Copy link
Contributor Author

That seems to settle it - we need to create a geofence on every sync if the state is WAITING_FOR_TRIP_START. If we can get weird crashes like this, and no geofence exit until we return to the spot, it is too risky to do anything else.

Note that we did not even get a geofence exit when we left Mountain View, only when we got to Berkeley. What if this place was in HI? We would never turn on tracking again, unless the phone was rebooted...

That would also solve issues around turning location tracking on and off...

@shankari
Copy link
Contributor Author

@shankari
Copy link
Contributor Author

This will also fix #128

@shankari
Copy link
Contributor Author

Ran into something similar again. This time, I was on my way to Berkeley when I checked to see if v1.9.0 was live, so that I could demo the targeted surveys to David. It was, so I installed the update right then. I remember that this was when I was sitting in the BART train at Millbrae BART, because I wondered whether the concrete cover would affect download speeds.

After that, all tracking was stopped until I manually turned it on the next afternoon in San Francisco. The rest of the trip to Berkeley, the trip from Berkeley to home, the trip from home to San Francisco.

Here's the related log.
loggerDB.no_tracking_my_phone_sat_morning.withdate.log.gz

Feb 24, 2017 ~ 12:20 AM, uploaded to store

Didn't launch updated app for a while.

123388,1487929450.86,2017-02-24 01:44:10.858000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123413,1487933045.97,2017-02-24 02:44:05.972000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123438,1487936970.71,2017-02-24 03:49:30.715000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123463,1487940914.62,2017-02-24 04:55:14.623000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123488,1487944813.12,2017-02-24 06:00:13.120000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123513,1487949327.25,2017-02-24 07:15:27.250000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123538,1487954657.18,2017-02-24 08:44:17.185000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
123563,1487958253.64,2017-02-24 09:44:13.638000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"

Launched updated app here, trying to initialize FSM.

123567,1487960610.89,2017-02-24 10:23:30.888000-07:53,UnifiedLogger : finished init of android native code
123568,1487960611.07,2017-02-24 10:23:31.070000-07:53,truncating obsolete entries before 1.485368611069E9
123569,1487960628.92,2017-02-24 10:23:48.922000-07:53,"DataCollectionPlugin : google play services available, initializing state machine"
123570,1487960629.05,2017-02-24 10:23:49.053000-07:53,"TripDiaryStateMachineReceiver : Setup not complete, sending initialize"

We start reading locations to create a geofence.

123578,1487960631.48,2017-02-24 10:23:51.477000-07:53,"TripDiaryStateMachineService : after reading from the prefs, the current state is local.state.waiting_for_trip_start"
123585,1487960637.63,2017-02-24 10:23:57.629000-07:53,"CreateGeofenceAction : Last location would have been Location[fused 37.715068,-122.453270 acc=1900 et=+27d15h33m36s886ms] if we hadn't reset it"
123594,1487960639.35,2017-02-24 10:23:59.354000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.715068,-122.453270 acc=1900 et=+27d15h34m9s725ms] from intent"
123602,1487960644.76,2017-02-24 10:24:04.761000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.715068,-122.453270 acc=1900 et=+27d15h34m15s30ms] from intent"
...
123715,1487960709.97,2017-02-24 10:25:09.975000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.715068,-122.453270 acc=1900 et=+27d15h35m20s274ms] from intent"

Changed, but still too low accuracy.

123720,1487960715.33,2017-02-24 10:25:15.327000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.716071,-122.452916 acc=1700 et=+27d15h35m25s309ms] from intent"
...
123965,1487960970.05,2017-02-24 10:29:30.048000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.716071,-122.452916 acc=1700 et=+27d15h39m39s938ms] from intent"

Changed, but still too low accuracy.

123970,1487960974.85,2017-02-24 10:29:34.854000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.722936,-122.445131 acc=1000 et=+27d15h39m44s978ms] from intent"
...
123985,1487960989.77,2017-02-24 10:29:49.765000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.722936,-122.445131 acc=1000 et=+27d15h40m0s76ms] from intent"

Changed, but still too low accuracy.

123990,1487961001.49,2017-02-24 10:30:01.491000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.777872,-122.414694 acc=1700 et=+27d15h40m10s694ms] from intent"
...
124163,1487961155.37,2017-02-24 10:32:35.368000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.777872,-122.414694 acc=1700 et=+27d15h42m45s300ms] from intent"

Changed, but still too low accuracy.

124168,1487961160.44,2017-02-24 10:32:40.436000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.784303,-122.404428 acc=1500 et=+27d15h42m50s337ms] from intent"
...
124241,1487961231.36,2017-02-24 10:33:51.359000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.784303,-122.404428 acc=1500 et=+27d15h44m1s32ms] from intent"

Changed, but still too low accuracy. Finally, we give up and don't create the geofence.
This should be OK because we should try to re-create the geofence on the next sync.
This is probably where we got the error with unable to load index.html

124246,1487961236.17,2017-02-24 10:33:56.175000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.784521,-122.403720 acc=1500 et=+27d15h44m6s80ms] from intent"
...
124248,1487961239.27,2017-02-24 10:33:59.269000-07:53,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"

Then, I re-launched the app.

124249,1487961589.72,2017-02-24 10:39:49.718000-07:53,UnifiedLogger : finished init of android native code
124250,1487961589.91,2017-02-24 10:39:49.907000-07:53,truncating obsolete entries before 1.485369589906E9
124251,1487961593.59,2017-02-24 10:39:53.590000-07:53,"DataCollectionPlugin : google play services available, initializing state machine"

Hm. we detect that setup is complete and we are in waiting_for_trip_start

124252,1487961593.78,2017-02-24 10:39:53.781000-07:53,"TripDiaryStateMachineReceiver : Setup complete, skipping initialize"
124257,1487961594.83,2017-02-24 10:39:54.833000-07:53,"TripDiaryStateMachineService : after reading from the prefs, the current state is local.state.waiting_for_trip_start"

This is because we update the version as soon as we broadcast the initialize.
We don't wait to see whether the geofence creation actually worked.
If we want to do this, we have to move the statemachine to start when this happens.

    ctxt.sendBroadcast(new Intent(ctxt.getString(R.string.transition_initialize)));
    SharedPreferences.Editor prefsEditor = sp.edit();
    // TODO: This is supposed to be set from the javascript as part of the onboarding process.
    // However, it looks like it doesn't actually work - it looks like the app preferences plugin
    // saves to local storage by default. Need to debug the app preferences plugin and maybe ask
    // some questions of the maintainer. For now, setting it here for the first time should be fine.
    prefsEditor.putInt(SETUP_COMPLETE_KEY, BuildConfig.VERSION_CODE);
    prefsEditor.commit();

But ok, we send an initialize again. I am not sure where this broadcast is coming from.
I do see that the service was restarted, so maybe the previous initialize is getting re-delivered?

124255,1487961594.52,2017-02-24 10:39:54.520000-07:53,TripDiaryStateMachineService : service started with flags = 1 startId = 1 action = local.transition.initialize
124256,1487961594.68,2017-02-24 10:39:54.680000-07:53,TripDiaryStateMachineService : service restarted! need to check idempotency!
124263,1487961597.26,2017-02-24 10:39:57.258000-07:53,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleStarted(local.transition.initialize) called

Ok so now we have a valid point finally and we create a geofence there. The
point is at around 880 and 7th street, so it doesn't appear to be very off. We
should also exit this geofence almost immediately.

124323,1487961634.96,2017-02-24 10:40:34.961000-07:53,"GeofenceLocationIntentService : Read location Location[fused 37.808235,-122.303276 acc=88 et=+27d15h50m29s529ms] from intent"
124327,1487961636.05,2017-02-24 10:40:36.052000-07:53,"CreateGeofenceAction : After waiting for location reading result, location is Location[fused 37.808235,-122.303276 acc=88 et=+27d15h50m29s529ms]"
124331,1487961637.36,2017-02-24 10:40:37.359000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused 37.808235,-122.303276 acc=88 et=+27d15h50m29s529ms]"
124333,1487961637.77,2017-02-24 10:40:37.767000-07:53,"CreateGeofenceAction : creating geofence at location 37.8082353, -122.3032764"
124336,1487961638.37,2017-02-24 10:40:38.365000-07:53,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start
124337,1487961638.43,2017-02-24 10:40:38.430000-07:53,TripDiaryStateMachineService : newState saved in prefManager is local.state.waiting_for_trip_start

screen shot 2017-02-27 at 9 35 44 am

But we don't. In fact, we don't get any geofence exit for the trip back from
Berkeley, and for the trip from Mountain View to San Francisco in the morning.

The next geofence exit occurs on the next afternoon when I turned on tracking
in San Francisco and then we start getting location points.

125072,1488064429.12,2017-02-25 15:13:49.122000-07:53,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleTripStart(local.transition.exited_geofence) called
125073,1488064429.27,2017-02-25 15:13:49.266000-07:53,CreateGeofenceAction : Removing geofence with ID = DYNAMIC_EXIT_GEOFENCE
...
125077,1488064429.91,2017-02-25 15:13:49.914000-07:53,LocationChangeIntentService : onCreate called

@shankari
Copy link
Contributor Author

This is similar to the prior case described in #127 (comment), except that:

  • we didn't get a null geofence exit
  • we didn't even exit the geofence when I passed through that location again on the way back from Berkeley in the evening.

During prior testing, if a geofence was created while in motion, on android, we would get a geofence exit immediately. on ios, we would not get a geofence exit, but we could query to see if we were within or outside of the geofence. I wonder if that behavior has changed in newer google play services. Now that I have an idea of what causes it, I can try to reproduce on the test phones, adding additional logging every time...

@shankari
Copy link
Contributor Author

Ran into a similar issue, reported by Hassan.

It's not sending me any trip end notifications.
Around a week ago.

@shankari
Copy link
Contributor Author

This is what I see from the logs:

Transitions seem to work fine until the 6th, and then there is a big gap until the 13th

10719,1488787205.63,2017-03-06 03:00:05.632000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.exited_geofence) calle"
11589,1488788117.89,2017-03-06 03:15:17.888000-07:53,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) calle"
11620,1488788296.53,2017-03-06 03:18:16.526000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.exited_geofence) calle"
12038,1488788571.55,2017-03-06 03:22:51.546000-07:53,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) calle"
21554,1489440954.75,2017-03-13 17:35:54.752000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.stop_tracking) calle"
21570,1489440960.23,2017-03-13 17:36:00.233000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.start_tracking) calle"

And then a big gap until the 14th and then the 16th.

21773,1489461593.17,2017-03-13 23:19:53.173000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.start_tracking) calle"
21823,1489465110.63,2017-03-14 00:18:30.627000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.start_tracking) calle"
23678,1489654854.5,2017-03-16 05:00:54.504000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
23739,1489658992.67,2017-03-16 06:09:52.668000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"

Multiple init calls around the 16th and then a stop followed by a start

23678,1489654854.5,2017-03-16 05:00:54.504000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
23739,1489658992.67,2017-03-16 06:09:52.668000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
23799,1489662600.68,2017-03-16 07:10:00.684000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
23900,1489669801.21,2017-03-16 09:10:01.210000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
24044,1489680758.19,2017-03-16 12:12:38.189000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
24107,1489684080.66,2017-03-16 13:08:00.662000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
24821,1489733168.0,2017-03-17 02:46:08-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.stop_tracking) calle"
24840,1489733170.65,2017-03-17 02:46:10.651000-07:53,"TripDiaryStateMachineService : handleAction(local.state.tracking_stopped, local.transition.start_tracking) calle"

@shankari
Copy link
Contributor Author

It looks like this is because location tracking was turned off.

Around the 6th, here's what happened

Trip ended, we moved to waiting_for_trip_start

12038,1488788571.55,2017-03-06 03:22:51.546000-07:53,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) calle"
12039,1488788571.55,2017-03-06 03:22:51.551000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.488788571549E9
12040,1488788571.55,2017-03-06 03:22:51.553000-07:53,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleTripEnd(local.transition.stopped_moving) called
12045,1488788571.62,2017-03-06 03:22:51.621000-07:53,"CreateGeofenceAction : creating geofence at location 37.8724134, -122.2706491"
12046,1488788571.68,2017-03-06 03:22:51.679000-07:53,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start

And then we exited the geofence, but we got an error while handling the exit
and never started tracking.

12051,1488789434.3,2017-03-06 03:37:14.296000-07:53,GeofenceExitIntentService : onCreate called
12052,1488789434.33,2017-03-06 03:37:14.330000-07:53,GeofenceExitIntentService : onStartCommand called with intent Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService launchParam=MultiScreenLaunchParams { mDisplayId=0 mFlags=0 } (has extras) } flags 0 startId 1
12053,1488789434.33,2017-03-06 03:37:14.332000-07:53,GeofenceExitIntentService : onStart called with startId 1
12054,1488789434.34,2017-03-06 03:37:14.336000-07:53,GeofenceExitIntentService : geofence exit intent action = null
12055,1488789434.34,2017-03-06 03:37:14.341000-07:53,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@98aeeb
12056,1488789434.34,2017-03-06 03:37:14.344000-07:53,GeofenceExitIntentService : got geofence intent callback with type -1 and location null
12057,1488789434.36,2017-03-06 03:37:14.355000-07:53,GeofenceExitIntentService : Found error 1000moving to start state

Looking at the code, it was generated from here

        } else if (parsedEvent.getGeofenceTransition() == -1) {
            // This must be a location services on/off transition
            // https://github.com/e-mission/e-mission-data-collection/issues/128#issuecomment-250304943
            if (parsedEvent.hasError()) {
                Log.i(this, TAG, "Found error "+parsedEvent.getErrorCode()+
                                "moving to start state");
                sendBroadcast(new Intent(getString(R.string.transition_tracking_error)));

According to the documentation
https://developers.google.com/android/reference/com/google/android/gms/location/GeofenceStatusCodes

1000 corresponds to GEOFENCE_NOT_AVAILABLE

Geofence service is not available now. Typically this is because the user turned off location access in settings > location access.

In that case, we should have generated a tracking_error transition according
to the code. But we didn't. We didn't get any further log messages until a sync
started. That code path is probably broken and I need to retest and fix it.

12057,1488789434.36,2017-03-06 03:37:14.355000-07:53,GeofenceExitIntentService : Found error 1000moving to start state
12058,1488792169.61,2017-03-06 04:22:49.610000-07:53,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.4887921696E9
12059,1488792169.62,2017-03-06 04:22:49.622000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.48879216962E9
12060,1488792170.47,2017-03-06 04:22:50.474000-07:53,ServerSyncAdapter : Starting sync with push

What happens on further inits? Let's the start_tracking transition from the 13th. It looks like it crashed again on init.

21570,1489440960.23,2017-03-13 17:36:00.233000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.start_tracking) calle"
21571,1489440960.24,2017-03-13 17:36:00.239000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.489440960238E9
21572,1489440960.24,2017-03-13 17:36:00.241000-07:53,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleTripStart(local.transition.start_tracking) called
21573,1489443793.32,2017-03-13 18:23:13.321000-07:53,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.489443793306E9
21574,1489443793.34,2017-03-13 18:23:13.336000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.489443793334E9
21575,1489443794.03,2017-03-13 18:23:14.027000-07:53,ServerSyncAdapter : Starting sync with push

And on the 16th.... Looks like geofence creation failed because we didn't get
any location, which would be consistent with turning location services off.

23678,1489654854.5,2017-03-16 05:00:54.504000-07:53,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) calle"
23679,1489654854.51,2017-03-16 05:00:54.513000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.489654854511E9
23680,1489654854.52,2017-03-16 05:00:54.515000-07:53,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleStarted(local.transition.initialize) called
23681,1489654854.55,2017-03-16 05:00:54.553000-07:53,CreateGeofenceAction : Last location would have been null if we hadn't reset it
23682,1489654854.56,2017-03-16 05:00:54.557000-07:53,"CreateGeofenceAction : mLastLocationTime = null, launching callback to read it and thencreate the geofence"
23683,1489654854.6,2017-03-16 05:00:54.602000-07:53,"CreateGeofenceAction : Successfully started tracking location, about to start waiting for location update"
23684,1489654854.61,2017-03-16 05:00:54.608000-07:53,CreateGeofenceAction : About to start waiting for location
23685,1489654854.68,2017-03-16 05:00:54.679000-07:53,GeofenceLocationIntentService : onCreate called
23686,1489654854.69,2017-03-16 05:00:54.686000-07:53,GeofenceLocationIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.actions.GeofenceLocationIntentService launchParam=MultiScreenLaunchParams { mDisplayId=0 mFlags=0 } (has extras) } startId 1
23687,1489654854.69,2017-03-16 05:00:54.690000-07:53,"GeofenceLocationIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.actions.GeofenceLocationIntentService launchParam=MultiScreenLaunchParams { mDisplayId=0 mFlags=0 } (has extras) }"
23688,1489654854.7,2017-03-16 05:00:54.702000-07:53,GeofenceLocationIntentService : Extras keys are [com.google.android.gms.location.EXTRA_LOCATION_AVAILABILITY]
23689,1489654854.71,2017-03-16 05:00:54.715000-07:53,GeofenceLocationIntentService : Read location null from intent
23690,1489655394.93,2017-03-16 05:09:54.930000-07:53,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.489655394911E9
23691,1489655394.95,2017-03-16 05:09:54.946000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.489655394943E9
23692,1489655395.66,2017-03-16 05:09:55.662000-07:53,ServerSyncAdapter : Starting sync with push

@shankari
Copy link
Contributor Author

shankari commented Jul 5, 2017

#127 (comment) is not really related to this - it is related to turning location services off.

@shankari
Copy link
Contributor Author

shankari commented Aug 3, 2017

This is the hostel

177,1501074077.28,2017-07-26 10:01:17.281000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,546635,-46,694265 acc=73 et=+1d12h50m39s505ms]"
178,1501074077.3,2017-07-26 10:01:17.298000-07:53,"CreateGeofenceAction : creating geofence at location -23.5466348, -46.6942646"

This is school

1156,1501074918.12,2017-07-26 10:15:18.118000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,562364,-46,722099 acc=32 et=+1d13h5m3s2ms]"
1157,1501074918.16,2017-07-26 10:15:18.158000-07:53,"CreateGeofenceAction : creating geofence at location -23.5623644, -46.7220989"

at the hostel

21200,1501126395.71,2017-07-27 00:33:15.708000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,548618,-46,692886 acc=25 et=+2d3h23m2s323ms alt=826.0 vel=0.0 bear=0.0]"
21201,1501126395.73,2017-07-27 00:33:15.734000-07:53,"CreateGeofenceAction : creating geofence at location -23.5486176, -46.6928857"

still at the hostel

21641,1501126688.58,2017-07-27 00:38:08.575000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,548583,-46,692925 acc=16 et=+2d3h27m55s328ms alt=821.0 vel=0.0 bear=0.0]"
21642,1501126688.59,2017-07-27 00:38:08.587000-07:53,"CreateGeofenceAction : creating geofence at location -23.5485834, -46.6929253"

still at the hostel

22346,1501130694.62,2017-07-27 01:44:54.625000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,548573,-46,693115 acc=13 et=+2d4h34m41s317ms alt=855.0 vel=0.0 bear=0.0]"
22347,1501130694.63,2017-07-27 01:44:54.633000-07:53,"CreateGeofenceAction : creating geofence at location -23.5485734, -46.6931154"

still at the hostel

22743,1501131053.88,2017-07-27 01:50:53.882000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,548577,-46,693106 acc=22 et=+2d4h40m40s417ms]"
22744,1501131053.89,2017-07-27 01:50:53.890000-07:53,"CreateGeofenceAction : creating geofence at location -23.5485766, -46.6931065"

at some weird location. Note that the accuracy is 151

23242,1501131474.8,2017-07-27 01:57:54.803000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23,544863,-46,690586 acc=151 et=+2d4h47m41s310ms vel=0.0 bear=0.0]"
23243,1501131474.82,2017-07-27 01:57:54.816000-07:53,"CreateGeofenceAction : creating geofence at location -23.5448632, -46.6905861"

What is the threshold for bad points for geofence creation?
The threshold is 200, so we got a bad location with a reasonable location.
Should just try to re-create the geofence every time.
No other solution for this.

@shankari
Copy link
Contributor Author

shankari commented Aug 3, 2017

Similar issues were reported by another user, but in her case it turned out that she was turning location tracking on and off manually. But we were not tracking even when the tracking was on (e.g. when she was using Uber). I don't think we listen to network on/off notifications.

@shankari
Copy link
Contributor Author

shankari commented Aug 3, 2017

Similar issues reported by one other user.

The last Location received was at

131560,1501681036.62,2017-08-02 10:37:16.619000-07:53,"LocationChangeIntentService : last10Points.length = 0 points5MinsAgo.length = 0 points, not enough to decide, returning false"

After this, we do not get ANY locations.

There is no reason why we should stop here

        if (last10Points.length < 10 || points5MinsAgo.length == 0) {
            Log.i(this, TAG, "last10Points.length = "+last10Points.length+
                    " points5MinsAgo.length = " + points5MinsAgo.length +
                    " points, not enough to decide, returning false");
            return false;
        }
    @Override
    protected void onHandleIntent(Intent intent) {
        if (validPoint && isTripEnded(last10Points, points5MinsAgo, tripEndSecs)) {
            // Stop listening to more updates
            Intent stopMonitoringIntent = new Intent();
            stopMonitoringIntent.setAction(getString(R.string.transition_stopped_moving));
            stopMonitoringIntent.putExtra(FusedLocationProviderApi.KEY_LOCATION_CHANGED, loc);
            sendBroadcast(stopMonitoringIntent);
            Log.d(this, TAG, "Finished broadcasting state change to receiver, ending trip now");
            // DataUtils.endTrip(this);
        }
    }

Why aren't we invoked again with a new location? The next log is from the regular sync!
Either there was some kind of crash that caused the OS to not wake up the
service, OR our logging is again not working with multi-threaded-ness....

131560,1501681036.62,2017-08-02 10:37:16.619000-07:53,"LocationChangeIntentService : last10Points.length = 0 points5MinsAgo.length = 0 points, not enough to decide, returning false"
131561,1501682101.48,2017-08-02 10:55:01.477000-07:53,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.50168210147E9
131562,1501682101.49,2017-08-02 10:55:01.488000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.501682101486E9

One thing to note is that just before this location, we actually did detect the
trip end, and stopped tracking.

131531,1501681036.3,2017-08-02 10:37:16.297000-07:53,TransitionNotificationReceiver : generating notification for event trip_ended and id = 737678
131532,1501681036.34,2017-08-02 10:37:16.338000-07:53,TripDiaryStateMachineService : onConnected(null) called
131533,1501681036.34,2017-08-02 10:37:16.340000-07:53,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) calle"
131534,1501681036.35,2017-08-02 10:37:16.350000-07:53,BuiltinUserCache : Added value for key background/battery at time 1.501681036347E9
131535,1501681036.36,2017-08-02 10:37:16.357000-07:53,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleTripEnd(local.transition.stopped_moving) called
131536,1501681036.38,2017-08-02 10:37:16.383000-07:53,ActivityRecognitionHandler : Stopping activity recognition with interval = 30000

So that might be why we don't get any more locations - we turned location
tracking off, and we got some rogue points before it actually turned off.

So when we detected the trip end, where did we create the geofence?

131537,1501681036.41,2017-08-02 10:37:16.414000-07:53,"CreateGeofenceAction : Last location would have been Location[fused -23.562288,-46.721908 acc=20 et=+11h42m41s576ms] if we hadn't reset it"
131538,1501681036.42,2017-08-02 10:37:16.419000-07:53,LocationChangeIntentService : onCreate called
131539,1501681036.42,2017-08-02 10:37:16.421000-07:53,"CreateGeofenceAction : Last location is Location[fused -23.562288,-46.721908 acc=20 et=+11h42m41s576ms] using it"

At the Biblioteca Brasiliana, which is correct.

Then while creating the geofence, we got some more points

131540,1501681036.43,2017-08-02 10:37:16.432000-07:53,LocationChangeIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 1
131542,1501681036.44,2017-08-02 10:37:16.442000-07:53,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.LocationChangeIntentService (has extras) }"
131545,1501681036.5,2017-08-02 10:37:16.499000-07:53,"LocationChangeIntentService : Read location Location[fused -23.562288,-46.721908 acc=20 et=+11h42m41s576ms] from intent"
131550,1501681036.56,2017-08-02 10:37:16.561000-07:53,LocationChangeIntentService : Finding points in the range 1.501680726561E9 < write_ts < 1.501681036561E9

And create the geofence in parallel

131541,1501681036.44,2017-08-02 10:37:16.438000-07:53,"CreateGeofenceAction : creating geofence at location Location[fused -23.562288,-46.721908 acc=20 et=+11h42m41s576ms]"
131543,1501681036.45,2017-08-02 10:37:16.450000-07:53,"CreateGeofenceAction : creating geofence at location -23.5622876, -46.7219083"
131547,1501681036.53,2017-08-02 10:37:16.526000-07:53,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start
131548,1501681036.53,2017-08-02 10:37:16.527000-07:53,LocationChangeIntentService : Finding the last 10 points
131549,1501681036.53,2017-08-02 10:37:16.533000-07:53,TripDiaryStateMachineService : newState saved in prefManager is local.state.waiting_for_trip_start
131551,1501681036.57,2017-08-02 10:37:16.569000-07:53,"TripDiaryStateMachineService : Service destroyed. So long, suckers!"

Then we finish processing this last spurious point.

131552,1501681036.58,2017-08-02 10:37:16.581000-07:53,LocationChangeIntentService : Current point status = true
131553,1501681036.59,2017-08-02 10:37:16.592000-07:53,BuiltinUserCache : Added value for key background/filtered_location at time 1.501681036586E9
131554,1501681036.6,2017-08-02 10:37:16.597000-07:53,"BuiltinUserCache : While searching for regex of last transition, got 1 results"
131555,1501681036.6,2017-08-02 10:37:16.599000-07:53,"BuiltinUserCache : 1.501681036182E9: {""currState"":""local.state.ongoing_trip"",""transition"":""local.transition.stopped_moving"",""ts"":1.50168103618E9}"
131556,1501681036.6,2017-08-02 10:37:16.604000-07:53,LocationChangeIntentService : After filtering at 1.501681036182E9 number of points goes from 10 -> 0
131557,1501681036.61,2017-08-02 10:37:16.610000-07:53,LocationChangeIntentService : After filtering at 1.501681036182E9 number of points goes from 5 -> 0
131558,1501681036.61,2017-08-02 10:37:16.614000-07:53,LocationChangeIntentService : last10Points.length = 0
131559,1501681036.62,2017-08-02 10:37:16.616000-07:53,LocationChangeIntentService : points5MinsAgo.length = 0
131560,1501681036.62,2017-08-02 10:37:16.619000-07:53,"LocationChangeIntentService : last10Points.length = 0 points5MinsAgo.length = 0 points, not enough to decide, returning false"

So the TripDiaryStateMachine is fine, appears to have created a geofence at
the correct location and exited properly. Is the geofence ever exited? No.

The geofence implementation on android seems to be really flaky in Brazil (see
also
#127 (comment)).
I should really try to re-create the geofence on every sync.

@shankari
Copy link
Contributor Author

From #127 (comment),

Similar issues reported by one other user.

It turned out that she was turning tracking off and on as well.

@shankari
Copy link
Contributor Author

ok so we were supposed to have handled location tracking turning off in 2da64dd

why isn't it working?

Apparently, I handled both the WAITING_FOR_TRIP_START and ONGOING_TRIP states.
Let us try to test and actually see what happens in those cases.

WAITING_FOR_TRIP_STATE

  • location services are on
  • turn location services off
  • nothing happens (no callbacks)
  • no notifications

what I expect to get:

  • R.string.transition_tracking_error

where is this generated

https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/GeofenceExitIntentService.java#L64

        } else if (parsedEvent.getGeofenceTransition() == -1) {
			// This must be a location services on/off transition
// https://github.com/e-mission/e-mission-data-collection/issues/128#issuecomment-250304943

@shankari
Copy link
Contributor Author

so apparently, we should get a transition with type -1
#128 (comment)

Let's check the documentation to see if it has changed.
Doesn't seem to have changed. Let's see whether I still get an intent.

@shankari
Copy link
Contributor Author

on connecting a debugger and retrying, got

D/GeofenceExitIntentService: got geofence intent callback with type -1 and location null
I/GeofenceExitIntentService: Found error 1000moving to start state
D

but then nothing. no transitions or anything.

@shankari
Copy link
Contributor Author

shankari commented Feb 17, 2019

ok so this is really stupid, but it is because we weren't listening to this notification in the AndroidManifest.xml. Now, we get the message in the receiver and generate the notification, but when the user click on it, we just launch the app instead of launching the location settings.

@shankari
Copy link
Contributor Author

we just launch the app instead of launching the location settings.

actually, we don't launch anything. It looks like that way of showing the getResolution() PendingIntent is just broken. We have to try other ways of handling that resolution.

@shankari
Copy link
Contributor Author

although getResolution() returns a PendingIntent, the documentation says

public PendingIntent getResolution ()

A pending intent to resolve the failure. This intent can be started with startIntentSenderForResult(IntentSender, int, Intent, int, int, int) to present UI to solve the issue.

so maybe this is a kind of PendingIntent that is not suitable for using with notifications. Jeez, I wish they would tell us :) But it also makes it harder to generate from a service, since the user is not necessarily looking at the UI at that exact time.

@shankari
Copy link
Contributor Author

Found another issue while debugging this. If the user tries to initialize when location services are turned off, the service stays in the start state but does not generate a notification notifying the user about this. This is particularly bad because one of our strategies for dealing with location services being turned off was that we would just try to notify periodically if we were in the start state.

e.g.

https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/TripDiaryStateMachineService.java#L361

                                // If we are not going to be able to create a geofence, then we don't
                                // want to go to waiting_for_trip_state, because then we will never exit
                                // from it. Instead, we go to state_start so that we will try to get
                                // out of it at every sync.

and

https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/TripDiaryStateMachineReceiver.java#L139

    public static void validateAndCleanupState(Context ctxt) {
        /*
         * Check for being in geofence if in waiting_for_trip_state.
         */
        if (TripDiaryStateMachineService.getState(ctxt).equals(ctxt.getString(R.string.state_start))) {
            Log.d(ctxt, TAG, "Still in start state, sending initialize...");
            ctxt.sendBroadcast(new Intent(ctxt.getString(R.string.transition_initialize)));
        } else if (TripDiaryStateMachineService.getState(ctxt).equals(
                ctxt.getString(R.string.state_waiting_for_trip_start))) {
            // We cannot check to see whether there is an existing geofence and whether we are in it.
            // In particular, there is no method to get a geofence given an ID, and no method to get the status of a geofence
            // even if we did have it. So this is not a check that we can do.
        }
    }

@shankari
Copy link
Contributor Author

It turns out that this is because we don't deal with failure to create the geofence by generating a notification. The last few logs from the failed geofence creation attempt are:

D/CreateGeofenceAction: After waiting for location reading result, location is null
D/CreateGeofenceAction: Was not able to read new location, skipping geofence creation
E

This maps to https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/actions/GeofenceActions.java#L80

so then we return null from GeofenceActions.create(). This is checked at
https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/TripDiaryStateMachineService.java#L445
but if the returned value is null, we don't do anything. We should either return null, or generate tracking_error or something. Should really think about structure, are we returning values directly, or generating broadcast messages or ???

@shankari
Copy link
Contributor Author

ok, so given our use cases, I think that the correct architecture is that we generate a broadcast message for tracking_error. This allows the transition notifier to also listen to the transitions and generate a customized message.

The challenge with doing this through the transition notifier is that if a particular client forgets to configure it, they can run into the same issue with it not working silently.

We could fix that by displaying the current english notification as backup if nothing is configured, and potentially localize that when we are localizing the native code.

@shankari
Copy link
Contributor Author

shankari commented Feb 17, 2019

ok so to return to #127 (comment) we actually need an activity to make this work.

So I can't do this directly from a service - I have to generate a notification, and then when that notification is clicked, and the activity is launched, I have to call these methods from the plugin code, which is where I have access to the activity.

@shankari
Copy link
Contributor Author

ok! so passing the pending intent as an object and then handling it in a new onNewIntent call in the plugin works. Making minor change to the interface to pass in the status directly because that seems like a nicer overall structure.

Next, need to solve the issue of generating a tracking_error when trying to create a geofence on initialization.

Also, might want to rationalize the code paths because on the turning off during geofencing now, we actually generate two notifications.

@shankari
Copy link
Contributor Author

shankari commented Feb 17, 2019

ok! so passing the pending intent as an object and then handling it in a new onNewIntent call in the plugin works. Making minor change to the interface to pass in the status directly because that seems like a nicer overall structure.

actually, we can't do this because in some of the places we pass in the PendingIntent for resolution, we get it from a ConnectionResult
https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/TripDiaryStateMachineService.java#L139

        ConnectionResult locResult = mApiClient.getConnectionResult(LocationServices.API);
        if (!locResult.isSuccess()) {
            if (locResult.hasResolution()) {
                NotificationHelper.createNotification(this, Constants.TRACKING_ERROR_ID, locResult.getErrorMessage(),
                        locResult.getResolution());
            } else {
                NotificationHelper.createNotification(this, Constants.TRACKING_ERROR_ID, locResult.getErrorMessage());
            }
}

and in others, it is from a Status object.

                public void onResult(BatchResult batchResult) {
                    String newState = fCtxt.getString(R.string.state_ongoing_trip);
                    if (batchResult.getStatus().isSuccess()) {
                       ...
                        if (batchResult.getStatus().hasResolution()) {
                            NotificationHelper.createNotification(fCtxt, STATE_IN_NUMBERS,
                                    "Error " + batchResult.getStatus().getStatusCode()+" while creating geofence",
batchResult.getStatus().getResolution());

If we move to new GoogleApi calls, we may be able to standardize on Status, but that is not going to happen right now.

@shankari
Copy link
Contributor Author

This may also explain why I have never received any complaints about this for iOS :)

@PatGendre
Copy link

Hi,@shankari, thanks, I downloaded the fixed apk but the install failed. Maybe because I use an Android 5 phone?

Nevertheless if I remember what you said there is way to end a trip manually in the dev zone? (actually I don't know what to do with the transition notify field)

@shankari shankari changed the title Tracking mysteriously suspended over multiple days Dealing gracefully with location services toggle Feb 26, 2019
@shankari
Copy link
Contributor Author

but the install failed. Maybe because I use an Android 5 phone?

Should work with android 5. The minSDKVersion is 18 which is 4.4.
What is the error that you get? Are you gunzipping the apk before install?
@hmharvey also said that she had errors with the installation, so maybe I will actually try this myself on a physical phone.

Nevertheless if I remember what you said there is way to end a trip manually in the dev zone? (actually I don't know what to do with the transition notify field)

Click on the pencil button next to the state and select "End Trip" (see video below)
manually_ending_trip.mp4.gz

@PatGendre
Copy link

Yes I installed the apk (not the gz). I had a simple message like "application not installed".

Thanks for the video ! I was not looking at the good place in the dev zone ui. It seems to have worked.

@shankari
Copy link
Contributor Author

Yes I installed the apk (not the gz). I had a simple message like "application not installed".

Did you install it directly from the phone or using apk install? If you use apk install, do you get a more detailed error message at the command prompt?

@PatGendre
Copy link

I installed it directly. I am out of the office now, I won't be able to try apk install until tomorrow, sorry.

@shankari
Copy link
Contributor Author

shankari commented Feb 26, 2019

@hmharvey @PatGendre I tried installing it on a physical device and there was a problem with how the apk was signed. Sorry! This newly signed version does work on my android 6 test phone. Let me know if you still have issues...

fix-location-services-release-correct-certs.apk.gz

$ ./adb install /tmp/fix-location-services-release-correct-certs.apk
/tmp/fix-location-services-release-correct...ushed. 4.1 MB/s (10500824 bytes in 2.437s)
	pkg: /data/local/tmp/fix-location-services-release-correct-certs.apk
Success

@PatGendre
Copy link

hi, i could install the fix but when i start it, i need a QR code, so i cannot use it. i see the error 6 instead of 1000 for absence of location though.

@shankari
Copy link
Contributor Author

Yes, as I said in #127 (comment), you need a QR code for this version. You can use the interscity branch/channel while testing or have me create one for you...

https://e-mission.eecs.berkeley.edu/#/client_setup?new_client=interscity&clear_usercache=true&clear_local_storage=true

@shankari
Copy link
Contributor Author

i see the error 6 instead of 1000 for absence of location though.

And when you click on the notification, it should open the app and ask you to enable location services

@PatGendre
Copy link

ok thanks, the app (network) is very slow but it works

@shankari
Copy link
Contributor Author

great! I should get feedback from @hmharvey and @deepalics0044 too and then I will merge everything and update the config.xml

@deepalics0044
Copy link

Testing the new apk:-

1) With location on
The toggle button in E-mission has been an issue always, sometimes I had to deliberately turn the toggle button on so that it starts tracking my trips.(it has a tendency of getting off).

2) With location off
The tracking toggle button goes to off state. (This I believe should happen)

3) With location on after off
The tracking toggle button should automatically go to on state but it doesn't.

I am testing the new apk I will let you know soon.

@shankari
Copy link
Contributor Author

shankari commented Mar 3, 2019

@deepalics0044 The profile screen doesn't automatically refresh. Try manually refreshing or killing the app and re-launching to see the real state.

@shankari
Copy link
Contributor Author

shankari commented Mar 3, 2019

sometimes I had to deliberately turn the toggle button on so that it starts tracking my trips.(it has a tendency of getting off).

Hm, this was possibly due to the location services toggle. At any rate, it should work now, specially if you refresh...

@shankari
Copy link
Contributor Author

shankari commented Mar 3, 2019

Testing the new apk:-
...
I am testing the new apk I will let you know soon.

So was your report with the old apk or the new one?

@deepalics0044
Copy link

It is working fine now. The toggle goes to on state as soon as I turn the location on. Trips are being recorded accordingly.

@shankari
Copy link
Contributor Author

shankari commented Mar 4, 2019

@deepalics0044 great! I will wait until tomorrow morning my time to give @hmharvey a chance to respond. But given that we have a couple of people validate this already, I am not inclined to wait any further. I will merge this fix, update config.xml and start working on the dynamic permissions on Monday morning my time.

Thanks all!

@indigok
Copy link

indigok commented Mar 4, 2019

Sorry, just now testing it. I seem to be having troubles with the tracking toggle button as well. Initially, I couldn't seem to turn it on, I got an "Error 1000 while creating geofence" even though my location was on. Turning my location off and back on manually seemed to fix it.

* location and tracking on: waiting_for_trip_start
* turned tracking off: tracking_stopped
* tracking back on: waiting_for_trip_start
* location off: notification (Error 6 in location settings)
* click notification: pop up (turn on location for better experience)
* -> ok on pop up: waiting_for_trip_start
* location off: notification ""
* ignored notification: tracking off and tracking_stopping
* location on manually: tracking still off and tracking_stopped (even after restarting the app)
* tracking turned on: waiting_for_trip_start
* turned location off & closed app
* turned location on & reopened: tracking on and waiting_for_trip_start

@shankari
Copy link
Contributor Author

shankari commented Mar 4, 2019

@deepalics0044 @hmharvey so just to clarify, the tracking toggle button currently only reflects whether the user turned tracking on/off for the emission app (e.g. whether it is in the tracking_stopped state or not).

There are basically two controls:

  • location services for the phone
  • tracking toggle for the app

So at least right now, this is expected behavior.

* location off: notification ""
* ignored notification: tracking off and tracking_stopping
* location on manually: tracking still off and tracking_stopped (even after restarting the app)
* tracking turned on: waiting_for_trip_start

Basically, the user said, "e-mission, please stop tracking me". Then you turned on location services on the phone, so for all apps. But you haven't yet allowed e-mission to start tracking you. It's only when you turn the tracking back on and say "e-mission, ok to track me again", that the FSM goes back to waiting_for_trip_start

If this is unclear, please suggest a way to rename the tracking button :)

@shankari
Copy link
Contributor Author

shankari commented Mar 4, 2019

I am going to merge this now and close this bug. But I would strongly encourage everybody to perform ongoing ad-hoc testing. So, not just while sitting at your desk, but also while you are out and about. If you find anything broken, please file another issue. Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants