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

manually start/stop caused incorrect trips to be stored #693

Closed
sichen1234 opened this issue Dec 9, 2021 · 34 comments
Closed

manually start/stop caused incorrect trips to be stored #693

sichen1234 opened this issue Dec 9, 2021 · 34 comments

Comments

@sichen1234
Copy link

Yesterday I used the developer zone start and stop trip feature to record a trip to and back from a location 5.8 miles away.

When I tried to refresh the diary it was stuck on "Reading user cache" for a long time.

Then it came back with 2 trips that were only 2km and 0.7 km

I can upload the loggerDB or the server side mongo db if that would help figure out what happened?

@sichen1234
Copy link
Author

Also I'm using a Samsung Galaxy S7 phone without a SIM card. Is a SIM card required to make it work?

@shankari
Copy link
Contributor

shankari commented Dec 9, 2021

I have test phones without a SIM card and they work reasonably fine although they sometimes have a large gap at the start. The developer zone start and stop is not really designed for manual trip tracking like Strava, that's why it is in the developer zone instead of in the main app functionality.

Once you have started the trip using the manual start, it will continue trying to detect a trip end as in the original FSM.

You can attach the logs, or you can expand them yourself (https://github.com/e-mission/e-mission-phone/blob/42706f3f40423f91d02db443e011f45b8385505d/README.md#beta-testing-debugging) and search for LocationChangeIntentService.*isTripEnded.*stoppedMoving

$ grep LocationChangeIntentService.*isTripEnded.*stoppedMoving ...

you can then see why we apparently detected a trip end after 2km.

@sichen1234
Copy link
Author

Thanks for the tip. Here is the logger for 2 trips yesterday. It started at around 12:02 PM and finished at 12:24 PM, and then at 13:40 PM and finished at 14:04 PM:

logger.20211208.txt.zip

The trips that show up in the Diary started 12:04 PM and ended 12:09 PM, then started at 1:50 PM and ended at 2:01 PM. So they were the beginning of the first trip and the end of the second trip.

The call to isTripEnded happened around 12:05 PM but the trip in the Diary didn't end at that time:
7983,1638993914.552,2021-12-08T12:05:14.552000-08:00,LocationChangeIntentService : last5MinsDistances = [0.6700864434242249] 7984,1638993914.555,2021-12-08T12:05:14.555000-08:00,"LocationChangeIntentService : last5MinsSpan = 5.174999952316284 secs, threshold + fuzz = 270" 7985,1638993914.557,2021-12-08T12:05:14.557000-08:00,LocationChangeIntentService : maxDistance = 6.367526054382324 TRIP_END_RADIUS = 100 7986,1638993914.561,2021-12-08T12:05:14.561000-08:00,LocationChangeIntentService : stoppedMoving: stoppedMoving = true 7987,1638993914.563,2021-12-08T12:05:14.563000-08:00,LocationChangeIntentService : isTripEnded: stoppedMoving = false

The trip ended at 12:09 PM but this is what's in the log:
8014,1638994171.973,2021-12-08T12:09:31.973000-08:00,ActivityRecognitionChangeIntentService : onStartCommand called with intent Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) } flags 0 startId 1 8015,1638994171.987,2021-12-08T12:09:31.987000-08:00,"ActivityRecognitionChangeIntentService : FINALLY! Got activity update, intent is Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.ActivityRecognitionChangeIntentService (has extras) }" 8016,1638994171.992,2021-12-08T12:09:31.992000-08:00,"ActivityRecognitionChangeIntentService : Detected new activity DetectedActivity [type=IN_VEHICLE, confidence=96]" 8017,1638994172.003,2021-12-08T12:09:32.003000-08:00,BuiltinUserCache : Added value for key background/motion_activity at time 1.638994172E9 8018,1638994172.008,2021-12-08T12:09:32.008000-08:00,ActivityRecognitionChangeIntentService : onDestroy called

Does this tell you anything to help understand what's going on?

@shankari
Copy link
Contributor

shankari commented Dec 9, 2021

@sichen1234 as you can see from the logs, we only read 8 locations in that entire duration and there was a big gap between noon, 1pm and 2pm. That's why we created two trips, one around noon and the other around 13:40.

$ grep "LocationChangeIntentService.*Read locations" logger.20211208.txt | wc -l
       8

$ grep "LocationChangeIntentService.*Read locations" logger.20211208.txt | cut -d "," -f 3
2021-12-08T12:02:30.252000-08:00
2021-12-08T12:02:35.554000-08:00
2021-12-08T12:05:14.403000-08:00
2021-12-08T12:13:37.567000-08:00
2021-12-08T12:13:37.873000-08:00

2021-12-08T13:40:23.238000-08:00

2021-12-08T14:01:22.058000-08:00
2021-12-08T14:01:22.146000-08:00

This is due to background restrictions in sending locations to the app. This is a known issue for Samsung phones - e.g. https://dontkillmyapp.com/
You need to turn off background restrictions for this app (and potentially for the entire phone) for everything to work properly. As you can see from the website, there's not much that the app developer can do.

Prior investigations of similar issues are:

@sichen1234
Copy link
Author

That was helpful. Thank you. So I went to the Battery in my Settings, Advanced Settings, and turned off App Power Monitor.

Now it is recording a lot more GPS locations:
loggerDB.20211209.withdate.log.zip

Still I was out between 3:07 PM, stopped in the middle, and came back around 3:30 PM. It only recorded a trip from 3:37 PM that ended at 4:01 PM well after I had stopped.

Is the log showing how it's deciding when a trip starts and ends?

@shankari
Copy link
Contributor

shankari commented Dec 10, 2021

@sichen1234

Is the log showing how it's deciding when a trip starts and ends?

Yup! In general, you can grep for the state transitions in the finite state machine. You can see the details of the FSM in my thesis.

$ grep "TripDiaryStateMachineService : handleAction.*called" loggerDB.20211209.withdate.log
10185,1639090802.309,2021-12-09T15:00:02.309000-08:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.exited_geofence) called"
12478,1639094501.215,2021-12-09T16:01:41.215000-08:00,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called"

There are typically geofence exit logs before the exited_geofence transition

10171,1639090802.074,2021-12-09T15:00:02.074000-08:00,GeofenceExitIntentService : onCreate called
10172,1639090802.086,2021-12-09T15:00:02.086000-08:00,GeofenceExitIntentService : onStartCommand called with intent Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService (has extras) } flags 0 startId 1
10173,1639090802.089,2021-12-09T15:00:02.089000-08:00,GeofenceExitIntentService : onStart called with startId 1
10174,1639090802.093,2021-12-09T15:00:02.093000-08:00,GeofenceExitIntentService : geofence exit intent action = null
10175,1639090802.106,2021-12-09T15:00:02.106000-08:00,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@fd53edc
10176,1639090802.112,2021-12-09T15:00:02.112000-08:00,"GeofenceExitIntentService : got geofence intent callback with type 2 and location ..."
10177,1639090802.116,2021-12-09T15:00:02.116000-08:00,GeofenceExitIntentService : Geofence exited! Intent = Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.GeofenceExitIntentService (has extras) } Starting ongoing monitoring...

And the "didn't move a lot in the last 10 minutes" checks before we detected that we stopped moving

12457,1639094501.017,2021-12-09T16:01:41.017000-08:00,LocationChangeIntentService : After filtering at -1.0 number of points goes from 10 -> 10
12458,1639094501.018,2021-12-09T16:01:41.018000-08:00,LocationChangeIntentService : After filtering at -1.0 number of points goes from 5 -> 5
12459,1639094501.019,2021-12-09T16:01:41.019000-08:00,LocationChangeIntentService : last10Points.length = 10
12460,1639094501.02,2021-12-09T16:01:41.020000-08:00,LocationChangeIntentService : points5MinsAgo.length = 5
12461,1639094501.022,2021-12-09T16:01:41.022000-08:00,"LocationChangeIntentService : last9Distances = [0.0, 1.1238300800323486, 5.148369312286377, 5.148369312286377, 5.1483693122
86377, 5.148369312286377, 5.997193336486816, 5.997193336486816, 5.997193336486816]"
12462,1639094501.024,2021-12-09T16:01:41.024000-08:00,"LocationChangeIntentService : last5MinsDistances = [0.0, 1.1238300800323486, 5.148369312286377, 5.148369312286377]"
12463,1639094501.026,2021-12-09T16:01:41.026000-08:00,"LocationChangeIntentService : last5MinsSpan = 264.4480001926422 secs, threshold + fuzz = 270"
12464,1639094501.027,2021-12-09T16:01:41.027000-08:00,LocationChangeIntentService : maxDistance = 5.997193336486816 TRIP_END_RADIUS = 100
12465,1639094501.028,2021-12-09T16:01:41.028000-08:00,LocationChangeIntentService : stoppedMoving: stoppedMoving = true
12466,1639094501.029,2021-12-09T16:01:41.029000-08:00,LocationChangeIntentService : maxDistance = 5.148369312286377 TRIP_END_RADIUS = 100
12467,1639094501.031,2021-12-09T16:01:41.031000-08:00,LocationChangeIntentService : stoppedMoving: stoppedMoving = true
12468,1639094501.032,2021-12-09T16:01:41.032000-08:00,LocationChangeIntentService : isTripEnded: stoppedMoving = true

These are consistent with your ground truth, so the issue must be with the actual points sensed at that time.

Looking at the first sensed point, it has accuracy 300m, which is pretty bad.

10251,1639091171.448,2021-12-09T15:06:11.448000-08:00,LocationChangeIntentService : onCreate called
10252,1639091171.467,2021-12-09T15:06:11.467000-08:00,LocationChangeIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 1
10253,1639091171.474,2021-12-09T15:06:11.474000-08:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.LocationChangeIntentService (has extras) }"
10254,1639091171.479,2021-12-09T15:06:11.479000-08:00,"LocationChangeIntentService : Extras keys are [com.google.android.location.LOCATION, com.google.android.gms.location.EXTRA_LOCATION_RESULT]"
10255,1639091171.494,2021-12-09T15:06:11.494000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx5094,-xx.xx6870 hAcc=300 et=+3d5h6m11s915ms alt=66.80461820545759 vAcc=6 sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1040]}], Location[fused xx.xx5094,-118.466870 hAcc=300 et=+3d5h8m14s83ms alt=66.80461820545759 vAcc=6 sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1228]}]] from intent"
10256,1639091171.515,2021-12-09T15:06:11.515000-08:00,LocationChangeIntentService : onStart called with Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.LocationChangeIntentService (has extras) } startId 2
10257,1639091171.521,2021-12-09T15:06:11.521000-08:00,BuiltinUserCache : Added value for key background/location at time 1.639091171517E9
10258,1639091171.541,2021-12-09T15:06:11.541000-08:00,BuiltinUserCache : Added value for key background/location at time 1.639091171536E9
10259,1639091171.545,2021-12-09T15:06:11.545000-08:00,LocationChangeIntentService : Finding the last 10 points
10260,1639091171.555,2021-12-09T15:06:11.555000-08:00,LocationChangeIntentService : Finding points in the range 1.639090861553E9 < write_ts < 1.639091171553E9
10261,1639091171.571,2021-12-09T15:06:11.571000-08:00,"LocationChangeIntentService : Found bad quality point Location[fused xx.xx5094,-118.466870 hAcc=300 et=+3d5h6m11s915ms alt=66.80461820545759 vAcc=6 sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1040]}] skipping"
10262,1639091171.58,2021-12-09T15:06:11.580000-08:00,LocationChangeIntentService : Current point status = false
10263,1639091171.589,2021-12-09T15:06:11.589000-08:00,"LocationChangeIntentService : Found bad quality point Location[fused xx.xx5094,-118.466870 hAcc=300 et=+3d5h8m14s83ms alt=66.80461820545759 vAcc=6 sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1228]}] skipping"
10264,1639091171.592,2021-12-09T15:06:11.592000-08:00,LocationChangeIntentService : Current point status = false
10265,1639091171.6,2021-12-09T15:06:11.600000-08:00,"BuiltinUserCache : While searching for regex of last transition, got 0 results"
10266,1639091171.606,2021-12-09T15:06:11.606000-08:00,"BuiltinUserCache : While searching for all, got 1 results"
10267,1639091171.609,2021-12-09T15:06:11.609000-08:00,"BuiltinUserCache : Considering transition 1.639090802297E9: {""currState"":""local.state.waiting_for_trip_start"",""transition"":""local.transition.exited_geofence"",""ts"":1.63909080229E9}"
10268,1639091171.613,2021-12-09T15:06:11.613000-08:00,LocationChangeIntentService : After filtering at -1.0 number of points goes from 0 -> 0
10269,1639091171.616,2021-12-09T15:06:11.616000-08:00,LocationChangeIntentService : After filtering at -1.0 number of points goes from 0 -> 0

10270,1639091171.62,2021-12-09T15:06:11.620000-08:00,"LocationChangeIntentService : FINALLY! Got location update, intent is Intent { cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.LocationChangeIntentService (has extras) }"
10271,1639091171.624,2021-12-09T15:06:11.624000-08:00,LocationChangeIntentService : Extras keys are [com.google.android.gms.location.EXTRA_LOCATION_AVAILABILITY]
10272,1639091171.628,2021-12-09T15:06:11.628000-08:00,LocationChangeIntentService : Read locations null from intent
10273,1639091171.631,2021-12-09T15:06:11.631000-08:00,LocationChangeIntentService : availability = false
10274,1639091171.634,2021-12-09T15:06:11.634000-08:00,"LocationChangeIntentService : location is not available, move to start state?"
10275,1639091171.64,2021-12-09T15:06:11.640000-08:00,LocationChangeIntentService : onDestroy called

Grepping further,

$ egrep "LocationChangeIntentService.*(FINALLY|bad quality)" loggerDB.20211209.withdate.log

we see that you consistently get bad points until 15:44:26. Note that the good quality points have accuracy < 50m.

The algorithm ignores bad quality points (to avoid irregular trajectories) so the trip appears to start around 15:40.

I don't have a Galaxy S7, but when I tested with the Galaxy Edge S6, I had to turn off all power saving for the entire phone for decent tracking (#535 (comment)). See if there are additional power saving settings on your phone and if so, please disable them.

Sorry this is so painful, but there's a reason why Samsung phones are top on the dontkillmyapp list. Also, the instructions on the dontkillmyapp site are not always perfect. On the S9, another user also had to turn off "Medium Power Saving Mode" #528 (comment) although it is not listed.

So I think it is just a question of turning off optimizations until the tracking works properly.

@shankari
Copy link
Contributor

shankari commented Dec 10, 2021

Note also that when we get the "bad quality" points, they are identical down to the 6th place after the decimal point. That's another characteristic of bad quality points - it is pretty clear that the OS is returning some cached value instead of actually sensing the location points...

10424,1639092334.665,2021-12-09T15:25:34.665000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx3543,-118.465410 hAcc=500 et=+3d5h29m42s169ms vAcc=??? sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=904]}]] from intent"
10450,1639092456.43,2021-12-09T15:27:36.430000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx3543,-118.465410 hAcc=500 et=+3d5h31m43s956ms vAcc=??? sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=904]}]] from intent"
10481,1639092577.605,2021-12-09T15:29:37.605000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx3543,-118.465410 hAcc=500 et=+3d5h33m43s289ms vAcc=??? sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1008]}]] from intent"
10502,1639092587.631,2021-12-09T15:29:47.631000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx3543,-118.465410 hAcc=500 et=+3d5h33m53s461ms vel=0.0 bear=90.0 vAcc=??? sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1008]}]] from intent"
10523,1639092597.446,2021-12-09T15:29:57.446000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx3543,-118.465410 hAcc=500 et=+3d5h34m3s314ms vel=0.0 bear=90.0 vAcc=??? sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1008]}]] from intent"
10544,1639092607.25,2021-12-09T15:30:07.250000-08:00,"LocationChangeIntentService : Read locations [Location[fused xx.xx3543,-118.465410 hAcc=500 et=+3d5h34m13s87ms vel=0.0 bear=90.0 vAcc=??? sAcc=??? bAcc=??? {Bundle[mParcelledData.dataSize=1008]}]] from intent"

@sichen1234
Copy link
Author

sichen1234 commented Dec 11, 2021

Thank you so much for your help with this. I set the phone to connect to wifi via a hotspot and use it along with GPS. I think the location readings are now much more accurate.
loggerDB.20211210.txt.zip

I used the phone's google map navigation during the morning trip, so the locations for the morning trip were pretty acurate:
Screenshot_20211210-132805_emission

On the way back, the google map was not running, so the locations were not as accurate. I took exactly the same path as in the first screenshot.
Screenshot_20211210-164404_emission

So my questions are:
I got to the destination at 11:43 AM (11:43:27.89700 reading in the log) and I was at the same spot at 11:53:39.413. I see in the log

20437,1639166019.633,2021-12-10T11:53:39.633000-08:00,"LocationChangeIntentService : last10Points.length = 10 points5MinsAgo.length = 0 points, not enough to decide, returning false"

So why didn't it decide to end trip until 12:17:
22936,1639167459.946,2021-12-10T12:17:39.946000-08:00,BuiltinUserCache : Added value for key background/location at time 1.639167459943E9 22937,1639167459.949,2021-12-10T12:17:39.949000-08:00,LocationChangeIntentService : Finding the last 10 points 22938,1639167459.966,2021-12-10T12:17:39.966000-08:00,LocationChangeIntentService : Finding points in the range 1.639167149965E9 < write_ts < 1.639167459965E9 22939,1639167459.976,2021-12-10T12:17:39.976000-08:00,LocationChangeIntentService : Current point status = true 22940,1639167459.982,2021-12-10T12:17:39.982000-08:00,BuiltinUserCache : Added value for key background/filtered_location at time 1.639167459979E9 22941,1639167459.988,2021-12-10T12:17:39.988000-08:00,"BuiltinUserCache : While searching for regex of last transition, got 0 results" 22942,1639167459.995,2021-12-10T12:17:39.995000-08:00,"BuiltinUserCache : While searching for all, got 1 results" 22943,1639167459.998,2021-12-10T12:17:39.998000-08:00,"BuiltinUserCache : Considering transition 1.639164292803E9: {""currState"":""local.state.waiting_for_trip_start"",""transition"":""local.transition.exited_geofence"",""ts"":1.639164292797E9}" 22944,1639167460.0,2021-12-10T12:17:40-08:00,LocationChangeIntentService : After filtering at -1.0 number of points goes from 10 -> 10 22945,1639167460.002,2021-12-10T12:17:40.002000-08:00,LocationChangeIntentService : After filtering at -1.0 number of points goes from 4 -> 4 22946,1639167460.005,2021-12-10T12:17:40.005000-08:00,LocationChangeIntentService : last10Points.length = 10 22947,1639167460.007,2021-12-10T12:17:40.007000-08:00,LocationChangeIntentService : points5MinsAgo.length = 4 22948,1639167460.009,2021-12-10T12:17:40.009000-08:00,"LocationChangeIntentService : last9Distances = [2.578204870223999, 46.0223503112793, 45.980438232421875, 45.80224609375, 45.54612731933594, 45.25426483154297, 45.37742614746094, 46.11195373535156, 47.198734283447266]" 22949,1639167460.012,2021-12-10T12:17:40.012000-08:00,"LocationChangeIntentService : last5MinsDistances = [2.578204870223999, 46.0223503112793, 45.980438232421875]" 22950,1639167460.014,2021-12-10T12:17:40.014000-08:00,"LocationChangeIntentService : last5MinsSpan = 243.68600010871887 secs, threshold + fuzz = 270" 22951,1639167460.016,2021-12-10T12:17:40.016000-08:00,LocationChangeIntentService : maxDistance = 47.198734283447266 TRIP_END_RADIUS = 100 22952,1639167460.019,2021-12-10T12:17:40.019000-08:00,LocationChangeIntentService : stoppedMoving: stoppedMoving = true 22953,1639167460.021,2021-12-10T12:17:40.021000-08:00,LocationChangeIntentService : maxDistance = 46.0223503112793 TRIP_END_RADIUS = 100 22954,1639167460.023,2021-12-10T12:17:40.023000-08:00,LocationChangeIntentService : stoppedMoving: stoppedMoving = true 22955,1639167460.025,2021-12-10T12:17:40.025000-08:00,LocationChangeIntentService : isTripEnded: stoppedMoving = true 22956,1639167460.044,2021-12-10T12:17:40.044000-08:00,"LocationChangeIntentService : Finished broadcasting state change to receiver, ending trip now"

  1. Why did it extrapolate a simpler path on the way back than on the way out? Here is the number of locations reads:

$ grep "LocationChangeIntentService.*" loggerDB.20211210.txt | grep '11:2' | grep 'Read location' | wc -l

11:2 70 11:3 34 11:4 18 11:5 2 12:0 64 12:1 2 12:2 33 12:3 1 12:4 1 12:5 3

Is the google map running causing it to read more locations?

  1. At the end of the trip, I was at the same location from 24551 (12:55 PM) on but it didn't think the trip ended until 26684 (15:50).

Thanks for all your help. This is really interesting :)

@shankari
Copy link
Contributor

Google navigation definitely causes it to read more locations (see section 5.2.1). The android location API performs sensor batching under the hood. And since the google map navigation is in the foreground, not the background, the background restrictions don't apply to it.

Note that, unlike traditional sensors, we don't control the hardware or the underlying OS. We get what we get from android/iOS and we need to do the best that we can with it.

20437,1639166019.633,2021-12-10T11:53:39.633000-08:00,"LocationChangeIntentService : last10Points.length = 10 points5MinsAgo.length = 0 points, not enough to decide, returning false"

This says that we don't have enough points to decide whether we have stopped (points5MinsAgo.length = 0) so we detect that we have not stopped (return false).

And indeed, after getting points every 30 secs consistently, we have a 10 min gap between 11:43 and 11:53.

19790,1639165363.15,2021-12-10T11:42:43.150000-08:00,LocationChangeIntentService : onCreate called
19963,1639165373.42,2021-12-10T11:42:53.420000-08:00,LocationChangeIntentService : onCreate called
20038,1639165375.049,2021-12-10T11:42:55.049000-08:00,LocationChangeIntentService : onCreate called
20069,1639165405.304,2021-12-10T11:43:25.304000-08:00,LocationChangeIntentService : onCreate called
20256,1639165410.091,2021-12-10T11:43:30.091000-08:00,LocationChangeIntentService : onCreate called


20408,1639166019.39,2021-12-10T11:53:39.390000-08:00,LocationChangeIntentService : onCreate called

Around 12:17, there were enough points (10 + 4)

22946,1639167460.005,2021-12-10T12:17:40.005000-08:00,LocationChangeIntentService : last10Points.length = 10 22947,1639167460.007,2021-12-10T12:17:40.007000-08:00,LocationChangeIntentService : points5MinsAgo.length = 4 

and the distances in both were < 100m, so we detected a stop.

Basically, the app requests location updates every 30 seconds so we can detect when the trip had ended. If the phone doesn't do this, the FSM will not work.

Again, I would suggest turning off medium power accuracy (Settings -> Device Management -> Battery) if you want the tracking to work properly. And/or use a different phone, one running stock android, such as a Pixel.

I set the phone to connect to wifi via a hotspot and use it along with GPS. I think the location readings are now much more accurate.

WiFi location detection relies on mapping WiFi signal strengths to known locations. So I am not sure this will help since the phone will just see that it is connected to the same WiFi network; it won't know that the "network" is actually a hotspot which is also moving. I have test phones with no SIM cards and no WiFi hotspot and:

  • the pixel phone works fine without any setting changes
  • the samsung works if I turn off power saving on the phone completely (Settings -> Device Management -> Power)

@shankari
Copy link
Contributor

@sichen1234 making the plug for turning off power saving completely, please see my previous results with Samsung phones:
#535 (comment)

The difference between the "mid" and "off" is essentially what you are seeing above.

@sichen1234
Copy link
Author

sichen1234 commented Dec 11, 2021 via email

@shankari
Copy link
Contributor

shankari commented Dec 11, 2021

Thanks. I did turn off all power savings in the Samsung.

@sichen1234 Could you send screenshots of your current power settings so I can confirm this?

Do you know if the iPhone is better? I can try that as well.

iPhone and (as I said earlier) Pixel (=stock android) will not have unexpected behavior. Even on Samsung, we have generally been able to track trips properly after we really turn off all the power settings.

Also is it the same reason why it didn’t think my second trip ended until 15:50 even though I was at the same location since 12:53?

Yes. At around 12:30 we were getting points multiple times a minute.

23786,1639168141.281,2021-12-10T12:29:01.281000-08:00,LocationChangeIntentService : onCreate called
23854,1639168141.946,2021-12-10T12:29:01.946000-08:00,LocationChangeIntentService : onCreate called
23877,1639168144.461,2021-12-10T12:29:04.461000-08:00,LocationChangeIntentService : onCreate called
23932,1639168146.132,2021-12-10T12:29:06.132000-08:00,LocationChangeIntentService : onCreate called
23955,1639168147.084,2021-12-10T12:29:07.084000-08:00,LocationChangeIntentService : onCreate called
23978,1639168148.091,2021-12-10T12:29:08.091000-08:00,LocationChangeIntentService : onCreate called
24001,1639168149.076,2021-12-10T12:29:09.076000-08:00,LocationChangeIntentService : onCreate called
24024,1639168150.057,2021-12-10T12:29:10.057000-08:00,LocationChangeIntentService : onCreate called
24047,1639168151.072,2021-12-10T12:29:11.072000-08:00,LocationChangeIntentService : onCreate called
24070,1639168152.087,2021-12-10T12:29:12.087000-08:00,LocationChangeIntentService : onCreate called
24093,1639168153.075,2021-12-10T12:29:13.075000-08:00,LocationChangeIntentService : onCreate called
24116,1639168154.054,2021-12-10T12:29:14.054000-08:00,LocationChangeIntentService : onCreate called
24139,1639168155.125,2021-12-10T12:29:15.125000-08:00,LocationChangeIntentService : onCreate called

After that, we went to on update roughly every 10 minutes.

24139,1639168155.125,2021-12-10T12:29:15.125000-08:00,LocationChangeIntentService : onCreate called
24207,1639168647.231,2021-12-10T12:37:27.231000-08:00,LocationChangeIntentService : onCreate called
24373,1639169118.158,2021-12-10T12:45:18.158000-08:00,LocationChangeIntentService : onCreate called
24547,1639169707.302,2021-12-10T12:55:07.302000-08:00,LocationChangeIntentService : onCreate called

and continued at that frequency....

26411,1639175940.859,2021-12-10T14:39:00.859000-08:00,LocationChangeIntentService : onCreate called
26435,1639176543.885,2021-12-10T14:49:03.885000-08:00,LocationChangeIntentService : onCreate called
26454,1639177260.591,2021-12-10T15:01:00.591000-08:00,LocationChangeIntentService : onCreate called
26473,1639178030.957,2021-12-10T15:13:50.957000-08:00,LocationChangeIntentService : onCreate called
26492,1639178631.211,2021-12-10T15:23:51.211000-08:00,LocationChangeIntentService : onCreate called

The app requests locations every 30 seconds, and expects to receive locations roughly every 30 secs. If it receives locations every 10 minutes, the end detection algorithm won't necessarily work properly.

@sichen1234
Copy link
Author

This is where I turned off my battery settings -- is it correct?
Screenshot_20211213-083522_Device maintenance

Does the log show why the app switched to requesting locations every 10 minutes?

@shankari
Copy link
Contributor

shankari commented Dec 13, 2021

That checks the boxes on "off" power saving mode, and turned off App power monitor.
Did you also ensure that the app is not sleeping and not optimized as outlined here:
#535 (comment)

Does the log show why the app switched to requesting locations every 10 minutes?

The app continues to request locations every 30 seconds. The phone OS (android) does not provide locations at the requested frequency because of background restrictions.

@sichen1234
Copy link
Author

Yes, I did turn off the "Optimize Battery Usage":
Screenshot_20211213-085004_Settings

I don't see separate screens for Device maintenace -> Battery -> Unmonitored apps and Device Management -> Power. My last screenshot is for Device Maintenance > Battery, and I've turned Power saving mode to OFF (not even MID from #535. The only thing that sounds like "Device maintenace -> Battery -> Unmonitored apps" is that option for App power monitor for me. My Samsung Galaxy s7 is on the factory default Android 8.0

@shankari
Copy link
Contributor

yes, you definitely need "off" see the specific comment in #535 that I linked to.

My Samsung Galaxy s7 is on the factory default Android 8.0

Hm. that's weird. There are specific restrictions on android 8.0+ that send "location updates only a few times an hour" (https://developer.android.com/about/versions/oreo/background-location-limits). We need to start a foreground service along with a persistent notification to avoid this.

But I'd already checked out the logs and we weren't starting the foreground service because we detected that this is Pre-Oreo....

20306,1639165430.975,2021-12-10T11:43:50.975000-08:00,"TripDiaryStateMachineForegroundService : Pre-Oreo, no foreground service, no need to check for notification"

@shankari
Copy link
Contributor

shankari commented Dec 13, 2021

Wait a minute, on line 175, it looks like we are checking for > OREO instead of >= OREO

../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|90| if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|106| if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|163| if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {

../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|175| if(Build.VERSION.SDK_INT >Build.VERSION_CODES.O) {

../plugins/e-mission-data-collection/src//android/verification/SensorControlChecks.java|85| if (android.os.Build.VERSION.SDK_INT >= android.os.Build.VERSION_CODES.O) {

Gah!!! And I notice that you don't have any foreground notifications in any of your screenshots.

@sichen1234 can you:

  • change that line in TripDiaryStateMachineForegroundService to >= OR
  • upgrade to 8.1

and see if that fixes the problem.

A cheaper, non-code, non-upgrade check is to turn tracking off and on just before starting your trip.

Basically, you need to have a notification on the left hand side of the notification bar which says "Ready to take a trip" or "Yay! You are on a trip!". Then the tracking will be fine.

If this is indeed the problem, you've found a very subtle bug, thank you, and I will roll the fix into the current set of data collection plugin changes. I have tested on Oreo phones before (e.g. #567) but since they were on personal phones, I guess the phones had been upgraded to 8.1 instead of 8.0.

@sichen1234
Copy link
Author

Indeed I do have Android 8.0.0:
Screenshot_20211213-092953_Settings

How do I " to turn tracking off and on just before starting your trip."?

What does this mean? "have a notification on the left hand side of the notification bar which says "Ready to take a trip" or "Yay! You are on a trip!". " Should I see these as notifications from e-mission in my notification panel?

@shankari
Copy link
Contributor

How do I " to turn tracking off and on just before starting your trip."?

In the e-mission app, Profile -> Tracking toggle

What does this mean? "have a notification on the left hand side of the notification bar which says "Ready to take a trip" or "Yay! You are on a trip!". " Should I see these as notifications from e-mission in my notification panel?

Yup, on the left side of the notification panel (see the location icon next to the CanBikeCO icon in the screenshot below)

@shankari
Copy link
Contributor

@sichen1234 were you able to get the notification to show up, and confirm that the location trajectory is accurate in that case? If so, we can rename this issue to the fix for android 8.0 (> instead of >=) and I can go ahead with the fix...

@sichen1234
Copy link
Author

I tried start and stop tracking, and it didn't work. I'm going to test it with the code change and let you know.

@shankari
Copy link
Contributor

@sichen1234 when you turned the tracking off and on, did the notification for the foreground service show up?
If not, could you send me the logs for that time period to I can see whether the foreground service was created properly?

@sichen1234
Copy link
Author

Sorry I lost those logs when I installed the updated version. I'll try it again and get the logs.

@shankari
Copy link
Contributor

shankari commented Dec 16, 2021

@sichen1234 sounds good. If you haven't bumped up the version number for the updated version, you need to turn tracking off and on to reinitialize the FSM. If you have bumped up the version number (which you would need to for publishing the app, we would do it automatically)
https://github.com/e-mission/e-mission-data-collection/blob/master/src/android/location/TripDiaryStateMachineReceiver.java#L181

@shankari
Copy link
Contributor

@sichen1234 Also, please note whether the foreground service notification does show up this time or not.

@sichen1234
Copy link
Author

Here is an updated log:
loggerDB.20211217.withdate.log.zip

I think it is pushing in notifications regularly now. Yesterday there was a walking trip from about 10:40 to 10:55 which didn't get recorded. Today it recorded the driving trips in the morning. It's gathering a lot more location reads so maybe the trip start/stop records are more a function of the calibration of how it's determining the trips?

@shankari
Copy link
Contributor

@sichen1234 the start and stop tracking is not intended for use on every trip. It is intended for use when you don't want to be tracked for a period of time - e.g. when you are going on a multi-day backpacking trip and want to minimize battery drain.

Once you have started tracking, and the foreground notification is displayed, the trip start/end detection should be automatic.

In the case of the 10:40 walking trip, the trip started properly with a geofence exit

666,1639680294.651,2021-12-16T10:44:54.651000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

But at 10:55, it looks like you manually turned tracking off and on.

4033,1639680938.883,2021-12-16T10:55:38.883000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.stop_tracking flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
4064,1639680941.12,2021-12-16T10:55:41.120000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.start_tracking flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

So we went never detected "stopped moving" and did not segment the trip correctly.

Again, the start/stop tracking suggestion was a hack to get the foreground service notification to show up without code changes. With the code change, the notification should be on all the time in the top left part of your screen. And the trip start/stops should also be automatically detected.

I think it is pushing in notifications regularly now.

The foreground service notification should stay on continuously, not pushed periodically.

@shankari
Copy link
Contributor

Looking at the foreground service checks, it looks like it has indeed been on since 11:13 yesterday.

$ grep "checkForegroundN" loggerDB.20211217.withdate.log | head
4529,1639682031.23,2021-12-16T11:13:51.230000-08:00,"TripDiaryStateMachineForegroundService : In checkForegroundNotification, found 1 active notifications"
4734,1639685608.277,2021-12-16T12:13:28.277000-08:00,"TripDiaryStateMachineForegroundService : In checkForegroundNotification, found 1 active notifications"
...
35270,1639771860.718,2021-12-17T12:11:00.718000-08:00,"TripDiaryStateMachineForegroundService : In checkForegroundNotification, found 2 active notifications"
35576,1639775171.498,2021-12-17T13:06:11.498000-08:00,"TripDiaryStateMachineForegroundService : In checkForegroundNotification, found 1 active notifications"

and there were never zero notifications

$ grep "checkForegroundN.*0" loggerDB.20211217.withdate.log | wc -l
       0

@shankari
Copy link
Contributor

shankari commented Dec 17, 2021

Ah, and it looks like today morning you stopped doing the manual start/stop tracking, so we detected the trip start/end correctly.

$ grep "TripDiaryStateMachineRcvr.*onReceive" loggerDB.20211217.withdate.log | vim -
...
6946,1639762483.599,2021-12-17T09:34:43.599000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
25291,1639764333.282,2021-12-17T10:05:33.282000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.stopped_moving flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

25414,1639767081.991,2021-12-17T10:51:21.991000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
34544,1639769158.917,2021-12-17T11:25:58.917000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.stopped_moving flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

34603,1639769986.633,2021-12-17T11:39:46.633000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.exited_geofence flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
35151,1639770274.565,2021-12-17T11:44:34.565000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4073490, Intent { act=local.transition.stopped_moving flg=0x10 pkg=edu.berkeley.eecs.emission cmp=edu.berkeley.eecs.emission/.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

To recap, with the code fix, when the foreground service notification is active, you don't need to do anything special. Just let the app detect trips automatically.

@sichen1234
Copy link
Author

I tested it some more this weekend. It is working a lot better. So I think your fix for Android 8.0.0 is good and we can close this issue.

@shankari
Copy link
Contributor

shankari commented Dec 21, 2021

@sichen1234 In #693 (comment) I said that the phone works well if it doesn't have a SIM card. That is true if it is in a WiFi-rich environment, since android uses fused location that combines GPS, WiFi and cellular. But if you go to a location without a lot of WiFi routers (like I did while hiking today, @lgharib), and don't have a SIM card that can access cellular networks, then the trip start is detected only when I am almost home.

I should get a SIM card for my test phone and go hiking in the same location again 😄

@shankari
Copy link
Contributor

Closing this issue for now.

@shankari shankari reopened this Dec 21, 2021
shankari added a commit to shankari/e-mission-data-collection that referenced this issue Dec 21, 2021
We were using `>` in this one location, which meant that if the version was
exactly 8.0, then the foreground service would not be restarted when killed.

Tested by @sichen1234 as part of e-mission/e-mission-docs#693

```
../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|90| if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|106| if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {
../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|163| if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.O) {

../plugins/e-mission-data-collection/src/android/location/TripDiaryStateMachineForegroundService.java|175| if(Build.VERSION.SDK_INT >Build.VERSION_CODES.O) {

../plugins/e-mission-data-collection/src//android/verification/SensorControlChecks.java|85| if (android.os.Build.VERSION.SDK_INT >= android.os.Build.VERSION_CODES.O) {
```

This fixes e-mission/e-mission-docs#693
@shankari
Copy link
Contributor

@sichen1234 can you confirm that
e-mission/e-mission-data-collection@3f48d1f
is the change that you made to get this to work?

I can then close this issue.

@sichen1234
Copy link
Author

sichen1234 commented Dec 21, 2021 via email

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

No branches or pull requests

2 participants