e-mission / e-mission-data-collection Goto Github PK

View Code? Open in Web Editor NEW

4.0 4.0 19.0 27.42 MB

Repository for our own data collection

License: BSD 3-Clause "New" or "Revised" License

Java 55.32% Objective-C 39.85% JavaScript 4.33% HTML 0.50%

e-mission-data-collection's People

Contributors

Stargazers

Watchers

Forkers

shankari mogeng sfwatergit patricksup jeffdh5 codechix nikooo777 sunil07t ariasfelipe fabmob jf87 ericafenyo lynchying iantei louisg1337 the-bay-kay jgreenlee

e-mission-data-collection's Issues

Optimize power consumption during trips

We already use geofencing to minimize power consumption when the user is not taking a trip. However, once we have exited the geofence, we read the location and the activity continuously. This leads to excessive power drain in situations where the user is travelling all day.

We should tune the location and activity detection parameters during trips by tweaking the time and distance parameters to get the location less frequently during long trips and more frequently during short trips. For example if an automobile is driving at freeway speeds, we can turn off tracking until the next exit (Kalman filter?)

Fix race conditions between data collection and sync

The data collection/sync code almost works, but has the following race condition:

we read all messages and sync them to the server
we use the list of read messages and read the last timestamp
we delete all messages less than that timestamp

The problem with this will occur when we have multiple messages with the same timestamp. That can lead to the following scenario.

Let us assume that messages m1, m2 and m3 occur at time t
Let us assume that the read for the data sync occurs at time t, after we have received m1, but before we have received m2 and m3
Then, while we are transmitting data to the server, m2 and m3 arrive
When we clear messages, we will clear m1, m2 and m3

m2 and m3 will be lost.

This is not likely to be a serious race - the likelihood of having multiple messages with the same timestamp is unlikely, and our data is so noisy that we are likely to have dropped messages anyway.
But it would be good to return and plug this hole at some point.

Geofence is not exited a second time

Last week, I ran into an issue with ongoing collection. We were getting the weird duplicate updates from the android fused API. Because of this, we detected that the trip ended.

[362|1438902466898|8/6/15 4:07 PM|FINE]LocationChangeIntentService : last9Distances = [0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0]
[364|1438902466961|8/6/15 4:07 PM|FINE]LocationChangeIntentService : maxDistance = 0.0 TRIP_END_RADIUS = 100
[366|1438902466998|8/6/15 4:07 PM|FINE]LocationChangeIntentService : stoppedMoving = true
[368|1438902467032|8/6/15 4:07 PM|INFO]LocationChangeIntentService : stoppedMoving = true
[370|1438902467073|8/6/15 4:07 PM|FINE]LocationChangeIntentService : Finished broadcasting state change to receiver, ending trip now
[372|1438902467283|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : after reading from the prefs, the current state is local.state.ongoing_trip
[374|1438902467419|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver onConnected(null) called
[376|1438902467455|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called
[378|1438902467491|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver handleTripEnd(local.transition.stopped_moving) called
[380|1438902467538|8/6/15 4:07 PM|FINE]ActivityRecognitionHandler : Stopping activity recognition with interval = 30000
[382|1438902467605|8/6/15 4:07 PM|FINE]CreateGeofenceAction : mLastLocation has elapsed time = 281631965000000
[384|1438902467673|8/6/15 4:07 PM|FINE]CreateGeofenceAction : Last location is Location[fused 37.822129,-122.268920 acc=1873 et=+3d6h13m51s965ms] creating geofence
[386|1438902467717|8/6/15 4:07 PM|FINE]CreateGeofenceAction : creating geofence at location 37.8221287, -122.2689201
[388|1438902467796|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : newState after handling action is local.state.waiting_for_trip_start
[390|1438902467869|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : newState saved in prefManager is local.state.waiting_for_trip_start

Then, since the geofence was created in error, we exit it almost immediately.

[394|1438902467980|8/6/15 4:07 PM|FINE]GeofenceExitIntentService : onCreate called
[396|1438902468018|8/6/15 4:07 PM|FINE]GeofenceExitIntentService : onStartCommand called with intent Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.GeofenceExitIntentService (has extras) } flags 0 startId 1
[398|1438902468058|8/6/15 4:07 PM|FINE]GeofenceExitIntentService : onStart called with startId 1
[400|1438902468105|8/6/15 4:07 PM|FINE]GeofenceExitIntentService : geofence exit intent action = null
[402|1438902468157|8/6/15 4:07 PM|FINE]GeofenceExitIntentService : got geofence intent callback with type 2 and location Location[fused 37.822129,-122.268920 acc=1873 et=+3d6h13m51s965ms]
[404|1438902468201|8/6/15 4:07 PM|FINE]GeofenceExitIntentService : Geofence exited! Intent = Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.GeofenceExitIntentService (has extras) } Starting ongoing monitoring...
[406|1438902468307|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : after reading from the prefs, the current state is local.state.waiting_for_trip_start
[408|1438902468433|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver onConnected(null) called
[410|1438902468480|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver handleAction(local.state.waiting_for_trip_start, local.transition.exited_geofence) called
[412|1438902468521|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver handleTripStart(local.transition.exited_geofence) called
[414|1438902468556|8/6/15 4:07 PM|FINE]CreateGeofenceAction : Removing geofence with ID = DYNAMIC_EXIT_GEOFENCE

And because we are still getting the bad updates, we detect a trip end almost immediately.

[438|1438902469530|8/6/15 4:07 PM|FINE]LocationChangeIntentService : last9Distances = [0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0, 0.0]
[440|1438902469573|8/6/15 4:07 PM|FINE]LocationChangeIntentService : maxDistance = 0.0 TRIP_END_RADIUS = 100
[442|1438902469631|8/6/15 4:07 PM|FINE]LocationChangeIntentService : stoppedMoving = true
[444|1438902469677|8/6/15 4:07 PM|INFO]LocationChangeIntentService : stoppedMoving = true
[446|1438902469718|8/6/15 4:07 PM|FINE]LocationChangeIntentService : Finished broadcasting state change to receiver, ending trip now
[448|1438902469725|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : after reading from the prefs, the current state is local.state.ongoing_trip
[450|1438902469872|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver onConnected(null) called
[452|1438902469909|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called
[454|1438902469996|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : TripDiaryStateMachineReceiver handleTripEnd(local.transition.stopped_moving) called
[456|1438902470039|8/6/15 4:07 PM|FINE]ActivityRecognitionHandler : Stopping activity recognition with interval = 30000
[458|1438902470109|8/6/15 4:07 PM|FINE]CreateGeofenceAction : mLastLocation has elapsed time = 281631965000000
[460|1438902470164|8/6/15 4:07 PM|FINE]CreateGeofenceAction : Last location is Location[fused 37.822129,-122.268920 acc=1873 et=+3d6h13m51s965ms] creating geofence
[462|1438902470203|8/6/15 4:07 PM|FINE]CreateGeofenceAction : creating geofence at location 37.8221287, -122.2689201
[464|1438902470281|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : newState after handling action is local.state.waiting_for_trip_start
[466|1438902470339|8/6/15 4:07 PM|FINE]TripDiaryStateMachineReceiver : newState saved in prefManager is local.state.waiting_for_trip_start

And then we never get a Geofence exit message after that, although we continue logging for multiple hours until we run out of battery overnight.

[0|1438959967285|8/7/15 8:06 AM|INFO]AddDataAdapter : Push complete, now pulling
[2|1438959968343|8/7/15 8:06 AM|INFO]CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@429d9cb0 with status HTTP/1.1 200 OK
[4|1438959968409|8/7/15 8:06 AM|INFO]CommunicationHelper : Result Summary JSON = {"server_to_phone": []}

It looks like we are not able to create geofences in quick succession. Filtering by accuracy while detection trip end on the phone will help solve this problem.

Installing a new version or changing the config restarts tracking

I recently upgraded from v0.0.8 to v0.0.9 on a phone that had tracking stopped, and it started tracking again. I think that the duty cycling was turned off (it went directly to ongoing_trip), so the problem may be with the init transition not being handled properly in TripDiaryStateMachineServiceOngoing.

Note that one even more egregious case of this was fixed in 993a630
but as we move to more automatic updates, we want to ensure that we don't secretly start tracking again.

Using GSON to serialize standard android location classes causes crashes in native code

One of the advantages of using a generic usercache is that then we can use a standard serialization/deserialization mechanism such as gson. However, it turns out that using gson with the standard android classes can cause a segfault.

D/LocationChangeIntentService(26905): onCreate called
D/LocationChangeIntentService(26905): FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
I/DEBUG   (  952): *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
I/DEBUG   (  952): Build fingerprint: 'generic_x86_64/sdk_google_phone_x86_64/generic_x86_64:5.1/LKY45/1737576:eng/test-keys'
I/DEBUG   (  952): Revision: '0'
I/DEBUG   (  952): ABI: 'x86_64'
I/DEBUG   (  952): pid: 26905, tid: 27494, name: IntentService[L  >>> edu.berkeley.eecs.cfc_tracker <<<
I/DEBUG   (  952): signal 11 (SIGSEGV), code 128 (SI_KERNEL), fault addr 0x0
I/DEBUG   (  952):     rax 03ffffffffffffff  rbx 0000000000000004  rcx 00000000ffffffc2  rdx 00007f356e448a90
I/DEBUG   (  952):     rsi 20007f356af67008  rdi 0000000000000001
I/DEBUG   (  952):     r8  ffffffffffffffc2  r9  00007f356af67010  r10 000000000000006f  r11 00007f356af67000
I/DEBUG   (  952):     r12 0000000000000000  r13 00007f356b0005a0  r14 00007f356afd80e8  r15 0000000000000004
I/DEBUG   (  952):     cs  0000000000000033  ss  000000000000002b
I/DEBUG   (  952):     rip 00007f356e3e50cd  rbp 0000000000000000  rsp 00007f355ac99c90  eflags 0000000000010202
I/DEBUG   (  952): 
I/DEBUG   (  952): backtrace:
I/DEBUG   (  952):     #00 pc 00000000000860cd  /system/lib64/libc.so (je_arena_tcache_fill_small+413)
I/DEBUG   (  952):     #01 pc 00000000000a5f1e  /system/lib64/libc.so (je_tcache_alloc_small_hard+14)
I/DEBUG   (  952):     #02 pc 000000000009b19b  /system/lib64/libc.so (je_malloc+235)
I/DEBUG   (  952):     #03 pc 000000000004116f  /system/lib64/libsqlite.so
I/DEBUG   (  952):     #04 pc 000000000001ff22  /system/lib64/libsqlite.so
I/DEBUG   (  952):     #05 pc 000000000002008c  /system/lib64/libsqlite.so
I/DEBUG   (  952):     #06 pc 00000000000668ed  /system/lib64/libsqlite.so
I/DEBUG   (  952):     #07 pc 0000000000070c2e  /system/lib64/libsqlite.so (sqlite3_overload_function+174)
I/DEBUG   (  952):     #08 pc 0000000000075396  /system/lib64/libsqlite.so
I/DEBUG   (  952):     #09 pc 00000000000db93c  /system/lib64/libandroid_runtime.so
I/DEBUG   (  952):     #10 pc 0000000001491961  /data/dalvik-cache/x86_64/system@[email protected]

This is reported on the internet as well, although for a different library.
http://stackoverflow.com/questions/28110943/retrofit-native-crash-fatal-signal-11-sigsegv

This crash occurs very rarely on my physical phone, but consistently in the emulator while running the LocationTests, typically within 20 mins.

Come up with solution for resetting/restarting collection when config changes

Right now, we can only reconfigure through the UI, so I can add a plugin method to restart the data collection - albeit in a somewhat hacky way. But later, we may get configs that are pushed from the server. We need to be able to restart the collection in that case, but also we don't want to restart for every config push because nothing might have changed.

Some form of versioning might be useful, and will also solve the race with rw-documents from e-mission/cordova-server-sync#12

We should also come up with a less hacky version of restarting data collection!?

Fine location tracking does not start properly on geofence exit

Sometimes, when we start fine location tracking on a geofence exit, fine location tracking does not actually appear to start.

Here is an example:
On the test iphone3:

7:40: Application launched with LaunchOptionsLocationKey = NO
7:40: tripDiaryStateMachine = (null), relaunchLocationManager = 0, recreating the state machine
7:40: initializing with WAITING_FOR_TRIP_START
7:45: EXITED_GEOFENCE
7:45: started fine location tracking
7:45: TRIP_STARTED
7:45: WAITING_FOR_TRIP_START -> ONGOING_TRIP
7:45: pushAndClearData
7:45: no data
7:45: deleting geofence
7:45: TRIP_STARTED
7:45: pushAndClearData
7:45: no data
7:45: EXITED_GEOFENCE in silent push
7:45: pushAndClearData
7:45: no data
7:45: TRIP_RESTARTED
7:45: pushAndClearData
7:45: no data
NO points!!
7:58: LaunchOptionsLocationKey = YES
7:58: initializing to ONGOING_TRIP
7:58: started fine location tracking
points received continously

Is the key perhaps that the app was already running when the geofence was exited?
Or is it just that the trip was largely over before the geofence triggered?

Looking at the points from the other iphones and from the android phones, it looks like the trip ended at around 7:52, so that does not appear to be the reason.
According to the android example,

Let's look at other examples.

visit notifications are not working correctly, at least on some phones

At least on @juemura's phone, we never seem to detect VISIT_STARTED events, only VISIT_ENDED. Since we stop tracking on VISIT_STARTED, we never stop tracking and so the power drain is very high.
This is the first case I have found of the visit transitions being incorrect.

Let's look at her logs more carefully....

199,1465499560.41,2016-06-09 13:05:40.405930-07:00,"Received visit notification = <...> +/- 40.77m (2016-06-09 19:07:39 +0000 to -)"
200,1465499560.54,2016-06-09 13:05:40.535080-07:00,"departure date is 4001-01-01 00:00:00 +0000, isDistantDate? 1, after distantDate? 0 "
201,1465499560.58,2016-06-09 13:05:40.583340-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"

This notification should be detected as a VISIT_START because it has no end time. However, our checks say isDistantDate? 1, after distantDate? 0

In the code,
https://github.com/e-mission/e-mission-data-collection/blob/master/src/ios/Location/TripDiaryDelegate.m#L256

    [LocalNotificationManager addNotification:[NSString stringWithFormat:@"departure date is %@, isDistantDate? %@, after distantDate? %@ ", visit.departureDate, @([visit.departureDate isEqualToDate:[NSDate distantFuture]]),
                                               @([visit.departureDate compare:[NSDate distantFuture]])] showUI:FALSE];
    if (visit.departureDate == [NSDate distantFuture]) {
        [[NSNotificationCenter defaultCenter] postNotificationName:CFCTransitionNotificationName
                                                            object:CFCTransitionVisitStarted];
    } else {
        [[NSNotificationCenter defaultCenter] postNotificationName:CFCTransitionNotificationName
                                                            object:CFCTransitionVisitEnded];
}

Clearly, the == check is failing although the log says that they are equal.
Ahahahah! The log uses isEqualToDate, the actual check uses ==. I guess those return the same result on the test phones, but not on all phones.

This should make it into this week's release.

iOS generates spurious updates with a distance filter

Based on the documentation from the iOS distance filter, we should not get updates until we have moved the distance specified. However, at least in areas with poor cell reception, such as the back of a residential address, we find that we get frequent updates even when the phone is sitting on a desk. At least some of these updates are between poor quality locations and the actual location of the phone.

For example, we get the following updates from a data collection app with a distance filter of 50 meters, while the phone was not in motion.

 {u'data': {u'accuracy': 65, u'fmt_time': u'2015-11-23T22:49:10-0800'}},
 {u'data': {u'accuracy': 50, u'fmt_time': u'2015-11-23T22:53:19-0800'}},
 {u'data': {u'accuracy': 10, u'fmt_time': u'2015-11-23T22:53:44-0800'}},
 {u'data': {u'accuracy': 7459.4864590168, u'fmt_time': u'2015-11-23T22:59:33-0800'}},
 {u'data': {u'accuracy': 65, u'fmt_time': u'2015-11-23T22:59:41-0800'}},
 {u'data': {u'accuracy': 5416.336059093475, u'fmt_time': u'2015-11-23T23:04:33-0800'}},
 {u'data': {u'accuracy': 5416.336059093475, u'fmt_time': u'2015-11-23T23:10:04-0800'}},
 {u'data': {u'accuracy': 25.02699322834155, u'fmt_time': u'2015-11-23T23:05:36-0800'}},
 {u'data': {u'accuracy': 3572, u'fmt_time': u'2015-11-23T23:10:04-0800'}},
 {u'data': {u'accuracy': 65, u'fmt_time': u'2015-11-23T23:10:04-0800'}},
 {u'data': {u'accuracy': 5254.714799642563, u'fmt_time': u'2015-11-23T23:15:04-0800'}},
 {u'data': {u'accuracy': 65, u'fmt_time': u'2015-11-23T23:16:47-0800'}},
 {u'data': {u'accuracy': 65, u'fmt_time': u'2015-11-23T23:20:21-0800'}},
 {u'data': {u'accuracy': 65, u'fmt_time': u'2015-11-23T23:24:27-0800'}}]

android FSM sometimes gets stuck in the waiting_for_trip_start state

While mucking with turning tracking on and off for the power measurement paper, I found that the android FSM sometimes gets stuck in the waiting_for_trip_start state and does not respond to any inputs. Initially, only one of the phones was in that state, but today morning, both of them were. I manually killed the process and restarted it and that fixed it for one of the phones.

Need to investigate and figure out what the underlying issue is.

Weird gaps in the trip end on the test android phone with the new code

Wonder if this is related to the logging change somehow.
I did launch the app and access the log to check the state, I think.

Points from the time I left home to the train station. I missed the 9:30, roughly. Transitions are:

73  2016-10-28T09:28:22.514278-07:00           1  (EXITED_GEOFENCE)
74  2016-10-28T09:28:22.853026-07:00           6  (TRIP_STARTED)
75  2016-10-28T09:28:23.061822-07:00           6  (TRIP_STARTED)
76  2016-10-28T09:28:23.213197-07:00           9  (TRIP_RESTARTED)
77  2016-10-28T09:30:04.050449-07:00           7  (RECEIVED_SILENT_PUSH)
78  2016-10-28T09:30:04.274220-07:00           8  (TRIP_END_DETECTED)
79  2016-10-28T09:30:05.132430-07:00          10  (END_TRIP_TRACKING)
80  2016-10-28T09:30:05.219475-07:00           2  (STOPPED_MOVING)

Why did it detect that we had stopped moving. I certainly hadn't stopped moving at 9:30.

On pulling the entries from the phone, I actually don't see a geofence transition at 9:28.

In fact, I don't see any logs for 9:28. The logs go from 9:23 -> 9:53

14820,1477668608.7,2016-10-28 09:23:08.704890-07:00,"Data pushed, fetch result = new data"
14821,1477670405.17,2016-10-28 09:53:05.172730-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"

Geofence exit is not triggered even when we move far way

I've seen this twice now in different phones, and they are completely bizarre.
Here's a concrete example:

We detect a trip end at

2016-02-24 18:53:15.530840-08:00    Received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP

We create a geofence at 6:53pm. Since I had the B/PAC meeting last night, this was right around City Hall.

2016-02-24 18:53:15.734590-08:00    About to start monitoring for region around (37.389476, -122.081559, 10.000000)

And when we created the geofence, we were inside it. So far, so good.

2016-02-24 18:53:16.221400-08:00    started monitoring for region STATIONARY_GEOFENCE_LOCATION
2016-02-24 18:53:16.787890-08:00     Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
2016-02-24 18:53:16.809020-08:00    Received INSIDE geofence state when currState = STATE_ONGOING_TRIP
2016-02-24 18:53:16.826770-08:00    Received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP
2016-02-24 18:53:17.113320-08:00    stopped fine location tracking
2016-02-24 18:53:17.173530-08:00    Received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP
2016-02-24 18:53:17.532440-08:00    Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START

And then we never get a geofence exit. We do get several location updates while we are in WAITING_FOR_TRIP_STATE.

2016-02-24 20:44:53.077270-08:00    In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.39037915,-122.08638911> +/- 5.00m
2016-02-25 09:26:48.867630-08:00    In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.39277437,-122.07941655> +/- 123.97m
2016-02-25 09:39:41.639110-08:00    In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.42929608,-122.14159016> +/- 65.00m
2016-02-25 09:52:21.416880-08:00    In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.48634181,-122.23190753> +/- 65.00m
2016-02-25 11:29:33.187610-08:00    In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.87251842,-122.26256453> +/- 65.00m

Why do these not trigger the geofence exit? The last of them is in Berkeley, for pity's sake. That is definitely away from Mountain View City Hall. Will add some additional debugging statements to understand.

Duty cycle location detection

Duty cycle location detection based on speed
Consider setting setFastestInterval(long) to 1 minute depending on the work that we do for each location update

SharedPreferences are sometimes not saved properly

It looks like SharedPreferences do not save properly in some cases.
Here's what I saw from the app logs for a trip in which I left Tied House at 8:30pm and came home.
The app appeared to have been killed and relaunched by the geofence exit, since the id was 9.

[9|1435807867723|7/1/15 8:31 PM|FINE]TripDiaryStateMachineReceiver : after reading from the prefs, the current state is local.state.waiting_for_trip_start

After processing the geofence exit, the new state was ongoing_trip.

[14|1435807867853|7/1/15 8:31 PM|FINE]TripDiaryStateMachineReceiver : newState after handling action is local.state.ongoing_trip

However, when the state is next read, it is still waiting_for_trip_start

[87|1435808413146|7/1/15 8:40 PM|FINE]TripDiaryStateMachineReceiver : after reading from the prefs, the current state is local.state.waiting_for_trip_start

So when the trip end is detected, we think that the current state is already waiting_for_trip_start,
so we do not turn off ongoing tracking, and we do not establish the geofence.

Make Francois' code available to the apps

Francois has a C++ implementation of the Viterbi algorithm, which we can use for path filtering. It would be nice to run this on the phone so that we have the option of doing more sophisticated initial processing at the phone layer instead of sending all the data to the server.
https://github.com/bellettif/MultimodePIF

Android

Fortunately, it turns out that android does support JNI, so this should not be too complicated.
https://developer.android.com/training/articles/perf-jni.html

So the primary task here is to build a JNI layer on top of Francois' class. You can use the same API that he uses for the python layer.

iOS

iOS already uses Objective C (we haven't switched to Swift), so this should be pretty easy. Again, you can use the same API that he uses for the python layer.

Feel free to contact @bellettif if you have questions.

Switch to dynamic permissions on android

Since Android 6.0 (marshmallow), the android system prompts for "dangerous" permissions at runtime. We use the location permission, which is dangerous.

So we need to switch to dynamic permissions and ensure that we don't crash if the permission is not granted.

We are building this app using apache cordova. So you need to follow the instructions for requesting location access (and any other dangerous permissions that are currently in plugin.xml). These instructions are in the cordova android plugin documentation.
https://cordova.apache.org/docs/en/6.0.0/guide/platforms/android/plugin.html

Then you need to update the API version, test the changes and make sure that the app does not crash.

Note that although the change is made here, in the plugin, you need to test using the e-mission-phone code, which uses the plugin.

Instructions to do that are in this README. You probably want to use the quick development method.
https://github.com/e-mission/e-mission-data-collection#quick-development-using-the-ide

"New data collection terms" message shows up even on first install

I just installed e-mission on my new phone and got the "new data collection terms" message, in spite of 9eb082b

On android, trip end is not detected when underground

When underground, or in other locations where the GPS is unable to have a fix, we keep getting invalid locations. Invalid locations are those with low accuracy. If we don't filter these, we detect a trip end every time we travel underground (e.g. on BART).
Filtering was added as part of
4286d60
and fixed several issues like
#45

But if we do filter them, then we don't detect a trip end even if we are stationary but underground, eg. in Soda 3rd floor.

I can't actually find logs for this right now, so I'll look around some more, otherwise I will just go and sit in the third floor for a while on Friday and get logs to attach here.

Prompt user to allow notifications to remind them to turn on tracking?

The original plan for e-mission consent, and the current implementation on android, envisaged that if the user did not consent to the data collection, we would prompt periodically to turn on data collection.

However, this is not easily achievable on iOS. On iOS, we do not receive notifications until the user has consented. We don't want to pop up the prompt to consent for notifications during pluginInitialize, because at that point, they haven't even got a chance to read the summary yet. We don't notify the native code of the transition between the summary page and the consent document, so we can't prompt then.

The real solution appears to be to prompt when the user says that they disagree. That's a useful hook into the data collection as well - markNotConsented in addition to markConsented, but I am not sure that I want to tackle that additional work right now. In particular, it is not clear that people will say "Yes", and we need to handle and test the case in which they say "No".

It is also not clear that prompting people continously to turn on tracking is a great user experience.

So for now, we bail on this for iOS. iOS and android behavior will be different and we will unify based on what people think. On iOS, if the user says that they disagree, there will be no further prompts or interaction until they launch the app again.

Crash while starting up emission on android

I found this using logcat

E/AndroidRuntime( 2497): java.lang.RuntimeException: Unable to start receiver edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver: android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5)
E/AndroidRuntime( 2497):    at android.app.ActivityThread.handleReceiver(ActivityThread.java:2431)
E/AndroidRuntime( 2497):    at android.app.ActivityThread.access$1500(ActivityThread.java:141)
E/AndroidRuntime( 2497):    at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1332)
E/AndroidRuntime( 2497):    at android.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime( 2497):    at android.os.Looper.loop(Looper.java:137)
E/AndroidRuntime( 2497):    at android.app.ActivityThread.main(ActivityThread.java:5103)
E/AndroidRuntime( 2497):    at java.lang.reflect.Method.invokeNative(Native Method)
E/AndroidRuntime( 2497):    at java.lang.reflect.Method.invoke(Method.java:525)
E/AndroidRuntime( 2497):    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:737)
E/AndroidRuntime( 2497):    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:553)
E/AndroidRuntime( 2497):    at dalvik.system.NativeStart.main(Native Method)
E/AndroidRuntime( 2497): Caused by: android.database.sqlite.SQLiteDatabaseLockedException: database is locked (code 5)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteConnection.nativeExecuteForLong(Native Method)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteConnection.executeForLong(SQLiteConnection.java:598)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteSession.executeForLong(SQLiteSession.java:652)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteStatement.simpleQueryForLong(SQLiteStatement.java:107)
E/AndroidRuntime( 2497):    at android.database.DatabaseUtils.longForQuery(DatabaseUtils.java:813)
E/AndroidRuntime( 2497):    at android.database.DatabaseUtils.longForQuery(DatabaseUtils.java:801)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteDatabase.getVersion(SQLiteDatabase.java:862)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:242)
E/AndroidRuntime( 2497):    at android.database.sqlite.SQLiteOpenHelper.getReadableDatabase(SQLiteOpenHelper.java:188)
E/AndroidRuntime( 2497):    at edu.berkeley.eecs.emission.cordova.usercache.BuiltinUserCache.getDocument(BuiltinUserCache.java:151)
E/AndroidRuntime( 2497):    at edu.berkeley.eecs.emission.cordova.tracker.ConfigManager.isConsented(ConfigManager.java:44)
E/AndroidRuntime( 2497):    at edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver.onReceive(TripDiaryStateMachineReceiver.java:86)
E/AndroidRuntime( 2497):    at android.app.ActivityThread.handleReceiver(ActivityThread.java:2424)
E/AndroidRuntime( 2497):    ... 10 more

No visit notifications, no geofence exits

Reported on one phone. It looks like it is stuck forever in WAITING_FOR_TRIP_START - it never gets the notification that a trip has started.

I use two techniques to determine that a trip has started:

visit entry and exit: this is supposed to be available for iOS 8.0+. The user is running iOS 10. Unsure why this doesn't work. Maybe Privacy -> Location Services -> System Services -> Frequent Locations is turned off?
geofence exit: user may have turned location services off and on for emission earlier. This might have deleted the geofence, similar to what happens on android. And since we are already in WAITING_FOR_TRIP_START, we assume that the geofence exists, and we don't try to recreate it. I can try to fix this in the code.

Hour long trip is not segmented properly

Trip to karate and back was treated as one trip although karate lesson is an hour long.

Seems to be related to #97 - the trip to karate is not detected as complete.

2016-03-01 01:09:02,973:DEBUG:------------------------------2016-02-29T16:09:51.401000-08:00------------------------------
2016-03-01 01:09:02,979:DEBUG:last5MinsDistances = [ 297.91792223  148.00903107   70.74334483   29.45781875   22.53231054
   21.60121787   21.32723947   21.72036211   20.93484013   21.51806829] with length 10
2016-03-01 01:09:02,983:DEBUG:last10PointsDistances = [ 148.00903107   70.74334483   29.45781875   22.53231054   21.60121787
   21.32723947   21.72036211   20.93484013   21.51806829    0.        ] with length 10, shape (10,)
2016-03-01 01:09:02,984:DEBUG:len(last10PointsDistances) = 10, len(last5MinsDistances) = 10
2016-03-01 01:09:02,984:DEBUG:last5MinsDistances.max() = 297.917922226, last10PointsDistance.max() = 148.009031074
2016-03-01 01:09:02,984:DEBUG:------------------------------2016-02-29T16:10:21.363000-08:00------------------------------
2016-03-01 01:09:02,990:DEBUG:last5MinsDistances = [ 148.25066524   81.19936214   38.68566061   41.56478288   42.52289453
   42.29461316   42.68804377   41.87371559   42.44075249   21.0572958 ] with length 10
2016-03-01 01:09:02,995:DEBUG:last10PointsDistances = [ 81.19936214  38.68566061  41.56478288  42.52289453  42.29461316
  42.68804377  41.87371559  42.44075249  21.0572958    0.        ] with length 10, shape (10,)
2016-03-01 01:09:02,995:DEBUG:len(last10PointsDistances) = 10, len(last5MinsDistances) = 10
2016-03-01 01:09:02,995:DEBUG:last5MinsDistances.max() = 148.25066524, last10PointsDistance.max() = 81.1993621395
2016-03-01 01:09:02,996:DEBUG:len(segmentation_points) == 0, early return

And the trip from karate is detected as a new trip with a new start.

2016-03-01 01:09:02,973:DEBUG:------------------------------2016-02-29T16:09:51.401000-08:00------------------------------
2016-03-01 01:09:02,979:DEBUG:last5MinsDistances = [ 297.91792223  148.00903107   70.74334483   29.45781875   22.53231054
   21.60121787   21.32723947   21.72036211   20.93484013   21.51806829] with length 10
2016-03-01 01:09:02,983:DEBUG:last10PointsDistances = [ 148.00903107   70.74334483   29.45781875   22.53231054   21.60121787
   21.32723947   21.72036211   20.93484013   21.51806829    0.        ] with length 10, shape (10,)
2016-03-01 01:09:02,984:DEBUG:len(last10PointsDistances) = 10, len(last5MinsDistances) = 10
2016-03-01 01:09:02,984:DEBUG:last5MinsDistances.max() = 297.917922226, last10PointsDistance.max() = 148.009031074

And we find its end

2016-03-01 02:08:59,936:INFO:Found trip end at 2016-02-29T17:03:53.396000-08:00

But the last place was at home

2016-03-01 02:08:59,949:DEBUG:last place doc = {u'enter_fmt_time': u'2016-02-29T08:47:50.
717000-08:00', u'user_id': UUID('e471711e-bd14-3dbe-80b6-9c7d92ecc296'), u'enter_local_dt
': datetime.datetime(2016, 2, 29, 8, 47, 50, 717000), u'ending_trip': ObjectId('56d4892c8
8f663446afb1396'), u'source': u'DwellSegmentationTimeFilter', u'location': {u'type': u'Po
int', u'coordinates': [-122.0859637, 37.3909514]}, u'enter_ts': 1456764470.717, u'_id': O
bjectId('56d4892c88f663446afb1397')}

So we say that all points from the last place are part of this trip. Normally, this would result in a straight line for part of the trip, but in this case, we actually did have points, so they were merged and we got the back and forth be part of the same trip.

It looks like the issue in which the phone stops collecting data at a point in which the server still doesn't see the trip is causing a bunch of issues.

initializing the google API client in onStartCommand() throws IllegalStateException

09-29 13:08:59.273  7699  7699 E AndroidRuntime: java.lang.IllegalStateException: Cannot 
invoke getConnectionResult unless GoogleApiClient is connected
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.interna
l.zzmg.getConnectionResult(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineService.onConnected(TripDiaryStateMachineService.java:130)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.common.internal.zzk.zzk(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.internal.zzmg.zzi(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.internal.zzme.zzpi(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.internal.zzme.onConnected(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.internal.zzmi.onConnected(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.internal.zzlz.onConnected(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.common.internal.zzj$zzg.zzqv(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.common.internal.zzj$zza.zzc(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.common.internal.zzj$zza.zzv(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.common.internal.zzj$zzc.zzqx(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.google.android.gms.common.internal.zzj$zzb.handleMessage(Unknown Source)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at android.os.Handler.dispatchMessage(Handler.java:102)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at android.os.Looper.loop(Looper.java:148)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at android.app.ActivityThread.main(ActivityThread.java:5417)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at java.lang.reflect.Method.invoke(Native Method)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
09-29 13:08:59.273  7699  7699 E AndroidRuntime:        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)

Dealing gracefully with location services toggle

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

Silent push is not reliably received on iOS

The original idea behind using the silent push was to get a more reliable delivery mechanism than the background fetch, which is known to be flaky. However, during the first active test on Wednesday, we found in practice that remote pushes were also sometimes missing.

Consider the list of transitions for the phone which was using the geofence.

Until the first trip outside, we got pushes reliably:

[{u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T00:13:21.843242-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T01:14:49.064150-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T02:08:56.893655-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T03:14:49.806864-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T04:13:39.781748-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T05:29:36.176499-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T06:13:51.828550-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T07:09:08.884717-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T08:06:30.322389-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T09:08:41.975411-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T10:07:48.680031-08:00'}},

After returning from the first trip at 10:35, I expected to get a remote push at around 11. But no remote push was delivered until 11:40, at which time I issued another call manually, which caused the geofence to be recreated.

 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T11:43:40.942893-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T11:43:40.942893-08:00'}},

Again, there was no remote push at noon, when we were in drama class. The next remote push was only delivered after we returned home and I generated a manual push at 1:11pm.

{u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},

After that, we receive consistent pushes until midnight with the 19:00 (7pm) and 22:00 (10pm) updates skipped.

{u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T14:20:00.524897-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T14:20:00.524897-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T15:00:04.690188-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T15:00:04.690188-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T16:00:06.035792-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T16:00:06.035792-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T17:00:04.928013-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T18:00:04.441931-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T18:00:04.441931-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T20:12:24.196366-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T21:14:52.841128-08:00'}}]

State machine gets wedged if location is not available on reboot

This was reported from the real world by Andy (Changun) from the ohmage team. The logs below are self-explanatory.

[1|1446862832708|11/6/15 9:20 PM|FINE]BootReceiver BootReceiver.onReceive called
[1|1446862841612|11/6/15 9:20 PM|FINE]TripDiaryStateMachineReceiver TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@25cb2fa8, Intent { act=local.transition.initialize flg=0x10 cmp=edu.berkeley.eecs.cfc_tracker/.location.TripDiaryStateMachineReceiver }) called
[3|1446862841638|11/6/15 9:20 PM|FINE]TripDiaryStateMachineService service started with flags = 0 startId = 1 action = local.transition.initialize
[5|1446862841657|11/6/15 9:20 PM|FINE]TripDiaryStateMachineService after reading from the prefs, the current state is local.state.waiting_for_trip_start
[7|1446862841953|11/6/15 9:20 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver onConnected(null) called
[9|1446862841970|11/6/15 9:20 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called
[11|1446862841985|11/6/15 9:20 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver handleStarted(local.transition.initialize) called
[13|1446862842004|11/6/15 9:20 PM|FINE]CreateGeofenceAction mLastLocationTime = null, launching callback to read it and thencreate the geofence
[15|1446862845725|11/6/15 9:20 PM|FINE]NotificationHelper Generating notify with id 78283 and message google API client connection suspendednetwork disconnected

As we can see, we tried to read the current location, and we couldn't, so we were not able to initialize the state machine, so we didn't read any values until he manually started the data collection.

We can also see that we re-initialize multiple other times:

[17|1446862908141|11/6/15 9:21 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver onConnected(null) called

[19|1446862908312|11/6/15 9:21 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called

[21|1446862908363|11/6/15 9:21 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver handleStarted(local.transition.initialize) called

[23|1446862908641|11/6/15 9:21 PM|FINE]CreateGeofenceAction mLastLocationTime = null, launching callback to read it and thencreate the geofence

We even do this after google play services is active, but we never get a response.

[25|1446863148931|11/6/15 9:25 PM|FINE]MainActivity Google Play services is available.
[27|1446863148975|11/6/15 9:25 PM|FINE]TripDiaryStateMachineReceiver TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@25cb2fa8, Intent { act=local.transition.initialize flg=0x10 cmp=edu.berkeley.eecs.cfc_tracker/.location.TripDiaryStateMachineReceiver }) called
[29|1446863148987|11/6/15 9:25 PM|FINE]TripDiaryStateMachineService service started with flags = 0 startId = 2 action = local.transition.initialize
[31|1446863148997|11/6/15 9:25 PM|FINE]TripDiaryStateMachineService after reading from the prefs, the current state is local.state.waiting_for_trip_start
[33|1446863149031|11/6/15 9:25 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver onConnected(null) called
[35|1446863149042|11/6/15 9:25 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called
[37|1446863149051|11/6/15 9:25 PM|FINE]TripDiaryStateMachineService TripDiaryStateMachineReceiver handleStarted(local.transition.initialize) called
[39|1446863149064|11/6/15 9:25 PM|FINE]CreateGeofenceAction mLastLocationTime = null, launching callback to read it and thencreate the geofence

We have some code that is supposed to check for this in two places, but it doesn't look like it does a great job...

        } else {
            Log.w(mCtxt, TAG, "mLastLocationTime = null, launching callback to read it and then" +
                    "create the geofence");
            return null;
        }
    }

        } else if (TripDiaryStateMachineService.getState(mContext).equals(
                mContext.getString(R.string.state_waiting_for_trip_start))) {
            // check in geofence
        }
    }

Location updates mysteriously pause

I am not sure whether this is a duplicate of #38 or not because the location updates haven't restarted yet (as of 5 hours later).

[197|1437098657839|7/16/15 7:04 PM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[212|1437098687864|7/16/15 7:04 PM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[227|1437098718024|7/16/15 7:05 PM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[242|1437098747910|7/16/15 7:05 PM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[257|1437098781068|7/16/15 7:06 PM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }

Activity updates are continuing.

[1100|1437114900203|7/16/15 11:35 PM|FINE]ActivityRecognitionChangeIntentService : FINALLY! Got activity update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.ActivityRecognitionChangeIntentService (has extras) }
[1105|1437114912136|7/16/15 11:35 PM|FINE]ActivityRecognitionChangeIntentService : FINALLY! Got activity update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.ActivityRecognitionChangeIntentService (has extras) }
[1110|1437114920679|7/16/15 11:35 PM|FINE]ActivityRecognitionChangeIntentService : FINALLY! Got activity update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.ActivityRecognitionChangeIntentService (has extras) }
[1115|1437114929119|7/16/15 11:35 PM|FINE]ActivityRecognitionChangeIntentService : FINALLY! Got activity update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.ActivityRecognitionChangeIntentService (has extras) }

It looks like the process was killed and restarted right around the time that the location updates stopped.

[263|1437098781480|7/16/15 7:06 PM|FINE]LocationChangeIntentService : stoppedMoving = false
[264|1437098781481|7/16/15 7:06 PM|INFO]LocationChangeIntentService : stoppedMoving = false
[0|1437098807300|7/16/15 7:06 PM|FINE]ActivityRecognitionChangeIntentService : FINALLY! Got activity update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.ActivityRecognitionChangeIntentService (has extras) }
[1|1437098807309|7/16/15 7:06 PM|FINE]ActivityRecognitionChangeIntentService : Intent extras are 0
[2|1437098807314|7/16/15 7:06 PM|FINE]ActivityRecognitionChangeIntentService : Intent extra key list 
is [com.google.android.location.internal.EXTRA_RELEASE_VERSION, com.google.android.location.internal.EXTRA_ACTIVITY_RESULT]

I plan to leave the phone plugged in all night and see if it resolves itself (i.e. is it a duplicate of #38 or not). Could this be caused by the OS deciding to pause location updates because power was low?

Remote push notifications not received until restart

So occasionally, we end up with no remote push notifications on iOS. This is not a problem with the remote push gateway or server code because other iOS phones do get the notification at the same time.

Example:

9101    2016-02-25 09:03:16.698750-08:00    Successfully registered remote push notifications with parse
10092   2016-02-25 15:10:07.573950-08:00    Received transition T_RECEIVED_SILENT_PUSH in state STATE_ONGOING_TRIP
10103   2016-02-25 15:10:08.314270-08:00    Received notification T_RECEIVED_SILENT_PUSH while processing silent push notification
10104   2016-02-25 15:10:08.333050-08:00    Ignoring SILENT_PUSH in the silent push handler
10125   2016-02-25 15:53:13.995960-08:00    Received transition T_RECEIVED_SILENT_PUSH in state STATE_WAITING_FOR_TRIP_START
10134   2016-02-25 15:53:15.960660-08:00    Received notification T_RECEIVED_SILENT_PUSH while processing silent push notification
10135   2016-02-25 15:53:15.987500-08:00    Ignoring SILENT_PUSH in the silent push handler
10157   2016-02-25 18:18:51.298910-08:00    Successfully registered remote push notifications with parse

and then no further notifications until at least 2016-02-26 12:00:00.

This could be due to several reasons:

If there is no network connectivity, we will not get remote push updates until connectivity is restored. I suspect that is what happened on the 25th - there was poor connectivity in the basement of the Tech.
But that cannot be the reason for the lack of remote push notifications from 18:18 to the next morning, when the phone was in the living room, right under the WiFi point. The code to register for remote notifications looks like this:

- (void)application:(UIApplication *)application
                    didRegisterForRemoteNotificationsWithDeviceToken:(NSData *)deviceToken {
    NSLog(@"Finished registering for remote notifications with token %@", deviceToken);
    // Store the deviceToken in the current installation and save it to Parse.
    PFInstallation *currentInstallation = [PFInstallation currentInstallation];
    [currentInstallation setDeviceTokenFromData:deviceToken];
    [currentInstallation saveInBackgroundWithBlock:^(BOOL succeeded, NSError *error) {
        if (succeeded) {
            [LocalNotificationManager addNotification:[NSString stringWithFormat:
                                                       @"Successfully registered remote push notifications with parse"]];
        } else {
            [LocalNotificationManager addNotification:[NSString stringWithFormat:
                                                       @"Error %@ while registering for remote push notifications with parse", error.description] showUI:TRUE];
        }
    }];
}

So it seems like if we start registering remote push notifications, but the background task doesn't complete, we won't log anything - neither that we started, nor that we failed. But we should still have the previous registration on parse, so it is not clear why this will fail. But maybe attempting a registration that then fails then causes remote pushes to fail.

Unfortunately, unlike #92, this is a hard problem to work around. If the push notifications are skipped because of poor connectivity, it is not clear what a reasonable solution/workaround would be. There's no point in re-registering since re-registering requires talking to a remote server and is likely to fail anyway. If the lack of remote pushes is due to something else, we could try re-registering when we get other calls - e.g. during visit notifications. But again, we can't know whether we are currrently registered, so we would need to re-register every time, which seems like overkill for a background operation.

Let's add some more logging and try to determine what exactly is going on before mucking with this further.

Phone data collection seems to end too early

Consider the trip for user 0763de67-f61e-3f5d-90e7-518e69793954 from 2016-02-29T08:35:35 to 2016-02-29T08:50:11. We almost end the trip on the server, but not quite.

2016-02-29 19:08:05,685:DEBUG:------------------------------2016-02-29T08:50:11.334000-08:00------------------------------
2016-02-29 19:08:05,692:DEBUG:last5MinsDistances = [ 102.61963128   80.7104769    56.41225835   53.43966631   21.01220394
   33.5300963    56.41225835   56.41225835    8.16762895   30.2536451
   56.41225835   20.89543077] with length 12
2016-02-29 19:08:05,697:DEBUG:last10PointsDistances = [ 53.43966631  21.01220394  33.5300963   56.41225835  56.41225835
   8.16762895  30.2536451   56.41225835  20.89543077   0.        ] with length 10, shape (10,)
2016-02-29 19:08:05,697:DEBUG:len(last10PointsDistances) = 10, len(last5MinsDistances) = 12
2016-02-29 19:08:05,697:DEBUG:last5MinsDistances.max() = 102.619631284, last10PointsDistance.max() = 56.4122583515
2016-02-29 19:08:05,697:DEBUG:len(segmentation_points) == 0, early return

Investigate why app preferences are stored in local storage by default instead of in the native app preferences

While initializing the plugin, we planned to use shared preferences to check whether initialization was complete. The expectation was that the shared preferences would be set at the end of the onboarding process
https://github.com/e-mission/e-mission-phone/blob/master/www/js/intro.js#L108
and we could just use it.

This preference seems to be set correctly, because when we read it here:
https://github.com/e-mission/e-mission-phone/blob/master/www/js/controllers.js#L10
it is true after the first init, but while reading it from native code, it is false.

This is probably because the app preferences appear to use local storage by default. Need to file an issue and investigate in depth. For now, we simply set it from native code and move on.

But need to investigate further and determine whether we should use the app preferences plugin, or just go back to sqlite instead.

Cache consented state?

We've cached the sensor config in the config manager, and we cache the consented state in the $rootScope in the javascript side. Maybe we should cache the consented state in the native data collection code as well.

Although it is only checked when an initialize transition is received, so it is not as critical as caching the config, which is used on an ongoing basis to detect when the trip should end, etc.

Switch long-term logging from the file handler to the database handler

I was trying to debug some phone behavior where it detected a trip end where no trip ended, in an attempt to determine why we are getting trip fragments in and around San Francisco, and I found some really bizarre behavior.

We got an update at 10:21

[42|1437067304025|7/16/15 10:21 AM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }

We checked the last 10 points, the last of which was generated at elapsed time = 52:49.

[45|1437067304303|7/16/15 10:21 AM|FINE]LocationChangeIntentService : last10Points = [Location[fused 37.586395,-122.360677 acc=40 et=+3d22h52m49s697ms],

We got another update at 10:22 with a last elapsed time of 22:53:18

[52|1437067333546|7/16/15 10:22 AM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[55|1437067333863|7/16/15 10:22 AM|FINE]LocationChangeIntentService : last10Points = [Location[fused 37.586395,-122.360677 acc=417 et=+3d22h53m18s689ms],

We got another update at 10:23 with a last elapsed time of 22:54:18

[2|1437067393477|7/16/15 10:23 AM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[5|1437067393921|7/16/15 10:23 AM|FINE]LocationChangeIntentService : last10Points = [Location[fused 37.593505,-122.379085 acc=1132 et=+3d22h54m18s725ms], Location[fused 37.586395,-122.360677 acc=417 et=+3d22h53m18s689ms],

Then, we had a data sync, also at 10:23, which runs in a separate thread

[0|1437067414228|7/16/15 10:23 AM|FINE]BuiltinUserCache : For row 0, about to send string {"data":{"mHasAccuracy":true,"mAltitude":0,"mHasAltitude":false,"mHasBearing":false
[56|1437067419395|7/16/15 10:23 AM|FINE]BuiltinUserCache : Clearing message for timequery 1437065622457 < 2131296319 < 1437067393511
[57|1437067419409|7/16/15 10:23 AM|FINE]BuiltinUserCache : Args =  write_ts > ? AND write_ts < ? : [1437065622457, 1437067393511]

And the next location update logged was at 10:33

[57|1437067419409|7/16/15 10:23 AM|FINE]BuiltinUserCache : Args =  write_ts > ? AND write_ts < ? : [1437065622457, 1437067393511]
[0|1437068020590|7/16/15 10:33 AM|FINE]LocationChangeIntentService : onCreate called
[1|1437068020595|7/16/15 10:33 AM|FINE]LocationChangeIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) } startId 1
[2|1437068020600|7/16/15 10:33 AM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }

And now the last location update read from the database was at elapsed time = 23:04:38. In fact, all entries have elapsed time > 23:00. How did entries from et = 22:54 to 23:00 without any logs in the file? The code logs the FINALLY statement before adding the point to the database.

37.599379,-122.386936 acc=40 et=+3d23h4m38s656ms],
37.599390,-122.386977 acc=40 et=+3d23h4m6s915ms],
37.599378,-122.386940 acc=913 et=+3d23h3m49s36ms],
37.599378,-122.386940 acc=913 et=+3d23h3m19s11ms],
37.599378,-122.386940 acc=913 et=+3d23h2m50s688ms],
37.599378,-122.386940 acc=913 et=+3d23h2m18s984ms],
37.599378,-122.386940 acc=913 et=+3d23h1m48s978ms],
37.599378,-122.386940 acc=913 et=+3d23h1m18s946ms],
37.599378,-122.386940 acc=979 et=+3d23h0m48s934ms],
37.599378,-122.386940 acc=979 et=+3d23h0m18s916ms]]

The only explanation that I can think of is that the lines were actually logged, but then were overwritten by the data sync logs. This would be consistent with a non-thread-safe FileHandler, in which the log statements for the location updates were overwritten by the data sync flushing its messages when being deallocated. That would also explain the gap.

I also see other such gaps during prior invocations of the user cache, although I haven't confirmed whether such errors occur ONLY during prior invocations.

Starting the sync

[24|1436811208280|7/13/15 11:13 AM|FINE]TripDiaryStateMachineReceiver : newState saved in prefManager is local.state.waiting_for_trip_start
[0|1436811372753|7/13/15 11:16 AM|FINE]BuiltinUserCache : For row 0, about to send string {"data":{"t
ransition":"local.transition.initialize","currState":"local.state.start"},"metadata":{"type":"message
","write_ts":1436811204562,"read_ts":0,"key":"statemachine\/transition"}}
...

Overlapping logs

[5|1436811649011|7/13/15 11:20 AM|FINE]BuiltinUserCache : For row 1, about to send string {"data":{"t
ransition":"local.transition.initialize","currState":"local.state.waiting_for_trip_start"},"metadata"
:{"type":"message","write_ts":1436811207767,"read_ts":0,"key":"statemachine\/transition"}}
[6|1436811649093|7/13/15 11:20 AM|SEVERE]AddDataAdapter : IO Error java.io.IOException while posting converted trips to JSON
[7|1436811649116|7/13/15 11:20 AM|SEVERE]AddDataAdapter : Error org.json.JSONException: End of input at character 0 of  while saving converting trips to JSON, skipping all of them
[8|1436811649591|7/13/15 11:20 AM|FINE]BuiltinUserCache : For row 0, about to send string {"data":{"t
ransition":"local.transition.initialize","currState":"local.state.start"},"metadata":{"type":"message
","write_ts":1436811204562,"read_ts":0,"key":"statemachine\/transition"}}

Big gap

[21|1436820543750|7/13/15 1:49 PM|FINE]BuiltinUserCache : Clearing message for timequery 1436819241344 < 2131296319 < 1436819486262
[22|1436820543756|7/13/15 1:49 PM|FINE]BuiltinUserCache : Args =  write_ts > ? AND write_ts < ? : [1436819241344, 1436819486262]
[0|1436821510397|7/13/15 2:05 PM|FINE]MainActivity : Google Play services is available.
[1|1436821510409|7/13/15 2:05 PM|INFO]TripDiaryStateMachineReceiver : noarg constructor called
[2|1436821510412|7/13/15 2:05 PM|INFO]TripDiaryStateMachineReceiver : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@41ff7af0, Intent { act=local.transition.initialize flg=0x10 cmp=edu.berkeley.eecs.cf

Losing log messages makes debugging well-nigh impossible, so this should be fixed ASAP.

Tracking mysteriously turned off on android

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.

New version of google play invokes the LocationService with an EXTRA_LOCATION_AVAILABILITY intent

This is apparently undocumented and causes our code to crash.

@scisley has graciously submitted a simple fix to prevent the crashes, but we should investigate this and see if we can actually use the extra information.
#30

Stackoverflow post with more details:
http://stackoverflow.com/questions/29960981/why-does-android-fusedlocationproviderapi-requestlocationupdates-send-updates-wi

Use a wrapper class for the activities as well

We already do this on iOS. On android, we are using gson directly, but the format is internal and is subject to change, and in fact did change when we bumped google play services versions.

it went from agb and agc to what looks like zzaEg and zzaEh, and of course, promptly broke all our formatting.

{u'zzaEg': 3, u'zzaEh': 92, u'mVersionCode': 1}, u'metadata': {u'write_ts': 1455096242, u'time_zone': u'America/Los_Angeles', u'platform': u'android', u'key': u'background/motion_activity', u'read_ts': 0, u'type': u'sensor-data'}}

We will work around this on the server now, but we really need to have a wrapper on the client that uses the public APIs. That will also make it easier to have a visualization of unpushed data on android.

battery level on iphone2 was much lower than on iphone1

While investigating the behavior of the iphones after reboot (https://github.com/e-mission/e-mission-server/issues/378#issuecomment-244172432), I noticed that of the two iPhones that I was testing one of them had much lower battery level than the other.

iPhone1: 74%
iPhone2: 16%

Checking the battery usage, it looked like emission was the main user.
I pulled the automatically logged battery data, and the battery level was almost identical until 5pm on the 31st when we left dance class.

iPhone 1

111     2016-08-31T16:00:08.950474-07:00    85.000000
116     2016-08-31T16:26:28.220186-07:00    83.000000
121     2016-08-31T17:00:05.247026-07:00    83.000000
125     2016-08-31T22:43:02.321156-07:00    81.000000
128     2016-08-31T22:45:29.233123-07:00    81.000000

iPhone 2

115     2016-08-31T16:00:13.057848-07:00    84.000000
119     2016-08-31T16:25:31.215741-07:00    83.000000
124     2016-08-31T17:00:04.391507-07:00    82.000000
128     2016-08-31T17:39:24.639105-07:00    81.000000
132     2016-09-01T11:53:11.614195-07:00    19.000000

Geofence exit in quick succession fails to start tracking

So some weird stuff happened yesterday that lead to us stopping tracking.
Here's what happened.

First trip end detected

First, we detected a trip end as normal. This was probably in San Francisco.

[27|1443648886637|9/30/15 2:34 PM|FINE]LocationChangeIntentService maxDistance = 43.841285705566406 TRIP_END_RADIUS = 100
[29|1443648886707|9/30/15 2:34 PM|FINE]LocationChangeIntentService stoppedMoving = true
[31|1443648886749|9/30/15 2:34 PM|FINE]LocationChangeIntentService stoppedMoving = true

And then we created a geofence and moved to waiting_for_trip_start

[51|1443648888275|9/30/15 2:34 PM|FINE]CreateGeofenceAction Last location is Location[fused 37.776300,-122.395146 acc=45 et=+11d21h7m34s532ms] creating geofence
[53|1443648888322|9/30/15 2:34 PM|FINE]CreateGeofenceAction creating geofence at location 37.7763, -122.3951455
[55|1443648888768|9/30/15 2:34 PM|FINE]TripDiaryStateMachineService newState after handling action is local.state.waiting_for_trip_start

Immediate exit

We received a geofence exit call almost immediately, roughly 3 minutes later.

[1|1443649034782|9/30/15 2:37 PM|FINE]GeofenceExitIntentService onCreate called
[9|1443649035116|9/30/15 2:37 PM|FINE]GeofenceExitIntentService got geofence intent callback with type 2 and location Location[fused 37.774513,-122.397353 acc=33 et=+11d21h10m3s624ms]

So we turned on location tracking

[29|1443649035883|9/30/15 2:37 PM|FINE]ActivityRecognitionHandler Starting activity recognition with interval = 30000
[39|1443649036072|9/30/15 2:37 PM|FINE]TripDiaryStateMachineService newState saved in prefManager is local.state.ongoing_trip

But it turned out that this was a bogus exit

Because the very first update that we received, right around the time that we saved the new state, even before the exit,

[43|1443649036157|9/30/15 2:37 PM|FINE]NotificationHelper Generating notify with id 78283 and message Success moving to local.state.ongoing_trip
[45|1443649036218|9/30/15 2:37 PM|FINE]LocationChangeIntentService Read location Location[fused 37.774513,-122.397353 acc=33 et=+11d21h10m3s624ms {Bundle[mParcelledData.dataSize=468]}] from intent
[47|1443649036258|9/30/15 2:37 PM|FINE]TripDiaryStateMachineService Service destroyed. So long, suckers!

was apparently within 100m of all the prior points.

Note that we are including a bunch of points from the prior trip (that just ended), instead of 10 points from the current trip. Note further that we have only one point for the current trip.

[57|1443649036627|9/30/15 2:37 PM|FINE]LocationChangeIntentService last9Distances = [17.880762100219727, 7.72879695892334, 19.795269012451172, 17.062000274658203, 17.6732120513916, 32.21595001220703, 34.96817398071289, 37.699275970458984, 47.67030334472656]
[59|1443649036681|9/30/15 2:37 PM|FINE]LocationChangeIntentService last5MinsDistances = [17.880762100219727, 7.72879695892334, 19.795269012451172, 17.062000274658203]
[61|1443649036727|9/30/15 2:37 PM|FINE]LocationChangeIntentService maxDistance = 47.67030334472656 TRIP_END_RADIUS = 100
[63|1443649036762|9/30/15 2:37 PM|FINE]LocationChangeIntentService stoppedMoving = true

Second geofence creation

So we create the geofence again

[91|1443649037372|9/30/15 2:37 PM|FINE]CreateGeofenceAction creating geofence at location 37.7745133, -122.397353
[93|1443649037459|9/30/15 2:37 PM|FINE]TripDiaryStateMachineService newState after handling action is local.state.waiting_for_trip_start
[95|1443649037558|9/30/15 2:37 PM|FINE]TripDiaryStateMachineService newState saved in prefManager is local.state.waiting_for_trip_start
[97|1443649037598|9/30/15 2:37 PM|FINE]NotificationHelper Generating notify with id 78283 and message Success moving to local.state.waiting_for_trip_start

Instantaneous exit

Again, we exit the geofence almost immediately, probably because the trip was not actually complete and we don't get to start tracking again. Instead we just die here.

[1|1443649068439|9/30/15 2:37 PM|FINE]GeofenceExitIntentService onCreate called
[3|1443649069082|9/30/15 2:37 PM|FINE]GeofenceExitIntentService onStartCommand called with intent Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.GeofenceExitIntentService (has extras) } flags 0 startId 1
[5|1443649069147|9/30/15 2:37 PM|FINE]GeofenceExitIntentService onStart called with startId 1
[7|1443649069185|9/30/15 2:37 PM|FINE]GeofenceExitIntentService geofence exit intent action = null

That is it. The next log is from the sync, almost 30 mins later.

[7|1443649069185|9/30/15 2:37 PM|FINE]GeofenceExitIntentService geofence exit intent action = null
[1|1443650579229|9/30/15 3:02 PM|FINE]BuiltinUserCache While searching for regex, got 1 results

Spurious trip tracking on android sometimes lasts for hours

We have always had an issue with geofences on android, in which it will randomly generate spurious geofence exits. We have always ignored these in the past, because they will auto-resolve after around 10 minutes, as we get enough points to detect a trip end.

However, on Android 6.0 in Doze mode, we may not get points immediately, since wake locks are turned off, and the app is only allowed to run during certain maintenance windows. It is not clear if this is a power drain, since presumably, the sensing will also be turned off during the doze window, but it would be good to fix if possible.

    latitude    longitude   accuracy    fmt_time
0   37.395463   -122.098333     1313.0  2015-12-01T04:07:30-08:00
1   37.395463   -122.098333     1313.0  2015-12-01T04:07:30-08:00
2   37.391018   -122.086195     30.0    2015-12-01T04:07:56-08:00
3   37.391018   -122.086215     30.0    2015-12-01T04:08:26-08:00
4   37.390999   -122.086227     30.0    2015-12-01T04:08:56-08:00
5   37.390999   -122.086227     30.0    2015-12-01T04:09:55-08:00
6   37.390999   -122.086227     30.0    2015-12-01T04:13:57-08:00
7   37.391016   -122.086196     31.5    2015-12-01T04:19:28-08:00
8   37.395504   -122.096731     1376.0  2015-12-01T07:49:17-08:00
9   37.391010   -122.086230     40.5    2015-12-01T07:50:01-08:00
10  37.391010   -122.086230     40.5    2015-12-01T07:50:47-08:00
11  37.391010   -122.086230     40.5    2015-12-01T07:51:17-08:00

iOS native code init takes a long time

Specially when the app is launched in the background, app init sometimes takes ~ 10-20 minutes. Here's one instance.

8246    2016-02-24 13:29:37.780600-08:00    Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
8247    2016-02-24 13:29:37.946080-08:00    started fine location tracking
8248    2016-02-24 13:29:38.059400-08:00    Received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START
8249    2016-02-24 13:29:38.335780-08:00    Moved from STATE_WAITING_FOR_TRIP_START to STATE_ONGOING_TRIP
8250    2016-02-24 13:29:38.358590-08:00    Received notification T_TRIP_STARTED while processing silent push notification
8251    2016-02-24 13:29:38.570830-08:00    Considering region with id = STATIONARY_GEOFENCE_LOCATION, location -121.889543, 37.331404
8252    2016-02-24 13:29:38.591660-08:00    Deleting it!!
8253    2016-02-24 13:29:38.614080-08:00    Received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP
8254    2016-02-24 13:29:38.660030-08:00    Received notification T_TRIP_STARTED while processing silent push notification
8255    2016-02-24 13:29:38.682070-08:00    Received notification T_EXITED_GEOFENCE while processing silent push notification
8256    2016-02-24 13:29:38.713460-08:00    Current state of region STATIONARY_GEOFENCE_LOCATION is 2 (outside)
8257    2016-02-24 13:29:38.729120-08:00    Received OUTSIDE geofence state when currState = STATE_ONGOING_TRIP
8258    2016-02-24 13:29:38.844450-08:00    Received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP
8259    2016-02-24 13:29:39.007380-08:00    Received notification T_TRIP_RESTARTED while processing silent push notification
8260    2016-02-24 13:29:39.043600-08:00    Successfully registered remote push notifications with parse
8261    2016-02-24 13:29:39.061620-08:00    Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true
8262    2016-02-24 13:44:19.405650-08:00    finished init of iOS native code
8263    2016-02-24 13:44:19.508920-08:00    Application launched with LaunchOptionsLocationKey = YES
8264    2016-02-24 13:44:19.527900-08:00    tripDiaryStateMachine = (null), relaunchLocationManager = 1, recreating the state machine
8265    2016-02-24 13:44:19.584380-08:00    Restart = 1, initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP
8266    2016-02-24 13:44:19.605660-08:00    started fine location tracking

Because of this, the trip back from the tech was largely a straight line with very little data. Need to investigate why this happens.

adding the "app launched" transition broke the android sync

39976,1456440668.991,ERROR,"ServerSyncAdapter : Error org.json.JSONException: Value app launched of type java.lang.String cannot be converted to JSONObject while saving converting trips to JSON, skipping all of them"

Need to look at accuracy of point before creating geofence in iOS

Currently, we create the geofence with the last location. But I recently had a case in which I was detected to be outside the geofence, so the trip restarted. Unclear why this might be, but one reason might be that we created the geofence based on a low accuracy trip.

We should filter the location by accuracy and only create a geofence when we have a high accuracy point.

Incorporate the GPS smoothing into the phone code

Once we have figured out an effective algorithm on the server side, integrate it into the phone so that the server gets pre-cleaned data. This depends on
https://github.com/e-mission/e-mission-server/issues/82

Location updates mysteriously pause for an hour and then mysteriously restart

Today, I went on a trip to the library.

I left at 5:16.

I got updates at 5:20 and 5:21, at which point we still hadn't detected that we had stopped moving.

[258|1436314856375|7/7/15 5:20 PM|FINE]LocationChangeIntentService : Intent Action is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[259|1436314856379|7/7/15 5:20 PM|FINE]DataUtils : addPoint(Location[fused 37.389004,-122.083822 acc=40 et=+4d5h30m52s636ms]) called
[260|1436314856423|7/7/15 5:20 PM|FINE]DataUtils : getLastPoints(10) called[261|1436314856424|7/7/15 5:20 PM|FINE]OngoingTripStorageHelper : selectStmt = SELECT * FROM TRACK_POINTS ORDER BY TIMESTAMP DESC LIMIT 10
[262|1436314856433|7/7/15 5:20 PM|FINE]OngoingTripStorageHelper : Found 10 locations that matched the statement
[263|1436314856435|7/7/15 5:20 PM|FINE]OngoingTripStorageHelper : Reading result at location 0
[264|1436314856437|7/7/15 5:20 PM|FINE]OngoingTripStorageHelper : Result is Location[DATABASE 37.389004,-122.083822 acc=40 et=+4d5h30m52s636ms]
.....
[285|1436314856485|7/7/15 5:20 PM|FINE]LocationChangeIntentService : maxDistance = 353.54705810546875 TRIP_END_RADIUS = 100
[286|1436314856487|7/7/15 5:20 PM|FINE]LocationChangeIntentService : stoppedMoving = false
[287|1436314856488|7/7/15 5:20 PM|INFO]LocationChangeIntentService : stoppedMoving = false

Then, at 5:22, we get an update, but we don't save anything into the database, and we don't check to see if we have stopped moving.

 [384|1436314952339|7/7/15 5:22 PM|FINE]LocationChangeIntentService : onCreate called
 [385|1436314952345|7/7/15 5:22 PM|FINE]LocationChangeIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) } startId 1
 [386|1436314952347|7/7/15 5:22 PM|FINE]LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
 [387|1436314952349|7/7/15 5:22 PM|FINE]LocationChangeIntentService : Extras keys are [com.google.android.gms.location.EXTRA_LOCATION_AVAILABILITY]
 [388|1436314952351|7/7/15 5:22 PM|FINE]LocationChangeIntentService : Intent Action is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }

Looking at the code, this is almost certainly because the location is null. I need to add some logging around that to verify.

Then, we get no further updates of the location until 6:17. It also looks like the app was killed and restarted in the interval since the log line IDs have been reset.

[387|1436314952349|7/7/15 5:22 PM|FINE]LocationChangeIntentService : Extras keys are [com.google.android.gms.location.EXTRA_LOCATION_AVAILABILITY]
[388|1436314952351|7/7/15 5:22 PM|FINE]LocationChangeIntentService : Intent Action is Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) }
[0|1436318223497|7/7/15 6:17 PM|FINE]LocationChangeIntentService : onCreate called
[1|1436318223504|7/7/15 6:17 PM|FINE]LocationChangeIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.cfc_tracker/.location.LocationChangeIntentService (has extras) } startId 1

It is completely unclear why this is happening. We are still asking for updates every 30 secs. It is supposed to wake up our IntentService and give us the updates. I don't know WTF is going on here.

Pushing data from phone to the server is not robust for a large number of entries

Our current technique for pushing data from the phone to the server involves reading all the data into memory and then pushing it to the server. This is not a robust solution since if we have large amounts of data on the phone, we get an out of memory error on the phone, and then basically the client becomes unable to push anything because every time it tries to push any data, it runs out of memory, which just increases the backlog for the next push.

Consent was revoked when updating to a new version

While testing the upgrade from 1.2.0 to 1.3.0, the consent appeared to be revoked.

2016-11-02 23:08:23.990 emission[634:468206] reqConsent = 2016-07-14, currConfig.approval_date = (null)
2016-11-02 23:08:23.991 emission[634:468206] DEBUG: reqConsent = 2016-07-14, currConfig.approval_date = (null)

But while restarting with the same version, it worked.

2016-11-02 23:19:35.435 emission[638:470332] BEMDataCollection:pluginInitialize singleton -> initialize statemachine and delegate
2016-11-02 23:19:35.438 emission[638:470332] data has 114 bytes, str has size 114
2016-11-02 23:19:35.465 emission[638:470332] reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14
2016-11-02 23:19:35.465 emission[638:470332] DEBUG: reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14
2016-11-02 23:19:35.481 emission[638:470332] isConsented = YES
2016-11-02 23:19:35.481 emission[638:470332] DEBUG: isConsented = YES

Restructure to remove dependency between logging and data collection

In response to user feedback, we don't stop showing alerts. But we still want to have an option to turn them on for debugging in case random stuff breaks down. My plan was to repurpose the existing simulate_user_interaction flag to do so. The problem is that then we have either:

logging depend upon data collection, which is ugh
or a bunch of copy pasted code in data collection + dependencies from all other modules into data collection, which is double ugh

I think that the real fix is to have a separate flag for showing debug messages in the UI. But that's going to take a lot more time to get right, so logging this and moving on.

Turning android location services on and off breaks tracking on e-mission

Couple of people have reported that tracking turns off when

First, here's what I see from the logs:

We detected that you stopped moving

2016-06-22 03:27:42.813000-07:00,LocationChangeIntentService : stoppedMoving = true
We tried to create a geofence at the location

2016-06-22 03:27:43.508000-07:00,"CreateGeofenceAction : creating geofence at location Location[fused acc=73 et=+6d12h53m19s775ms alt=640.0]"
Creation was successful, so we went dormant and waited a geofence exit event to signal the start of a new trip

2016-06-22 03:27:43.553000-07:00,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start

And we never got it. So my current theory is that you turned off location tracking at around that time (can you confirm?) and turning off location tracking deletes all registered geofences.

I am not sure whether manually turning on tracking from the app when location tracking was turned off would have prompted you to turn it on, but we didn't have a chance to do that because we were never invoked to start tracking.

And it is surprisingly hard to make this more robust. The app does get woken up every 1-2 hours for a bi-directional sync, so I can use that to try and recover from a bad state.

Note, however, that simply checking whether location tracking is currently on will not work because it might have been turned off and on between syncs and the geofence deleted.

What we really need to do is to check whether we have a geofence registered and to create one if we don't. Unfortunately, I've looked into this before as part of
#65
and amazingly, android does not have an API to check whether a geofence exists!

At this point, the only thing that I can think of doing is to create a geofence every time we are launched for a sync and there is no ongoing trip.

I'm going to think a bit about whether I really want to do this because it has the potential to backfire, but will probably implement it in next week's release.

Repeated iOS crashes reported by the app store

I've periodically seen waves of crashes reported by the app store.

The crash trace is

UserCache retrieval queries are ignoring the type field

Query strings use all other parameters, but omit the type from the query - e.g.

    public <T> T[] getLastValues(int keyRes, String type, int nEntries, Class<T> classOfT) {
        String queryString = "SELECT "+KEY_DATA+" FROM "+TABLE_USER_CACHE+
                " WHERE "+KEY_KEY+" = '"+getKey(keyRes)+ "'"+
                " ORDER BY write_ts DESC  LIMIT "+nEntries;

Unify android and iOS DataUtils

UPDATE of a non-existent entry seems to work on android but not on iOS.
Should probably change android version to be consistent
Conversion from dictionary -> json string in the existing phone code appears
to be broken. This is really weird. Switching to the new call appears to work.
Should port fix over e-mission-phone as well.