Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Trips represented by straight lines #1095

Open
shankari opened this issue Oct 24, 2024 · 29 comments
Open

Trips represented by straight lines #1095

shankari opened this issue Oct 24, 2024 · 29 comments

Comments

@shankari
Copy link
Contributor

shankari commented Oct 24, 2024

Report from PSU, who has been testing data collection

They took this trip (from roughly 205pm to 330pm)

image

and it was recorded as
image

Public issue created with permission (email dated Oct 24, with title "OpenPath questions about gaps in trips")

@shankari
Copy link
Contributor Author

Here's what I see in the logs:

Previous trip ended at 8:21

797,1727018467.76015,2024-09-22T08:21:07.760150-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"

New trip started at 13:50, including a VISIT_ENDED

833,1727038244.95052,2024-09-22T13:50:44.950520-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
836,1727038244.95445,2024-09-22T13:50:44.954450-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
844,1727038244.96454,2024-09-22T13:50:44.964540-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
847,1727038244.96749,2024-09-22T13:50:44.967490-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
856,1727038245.60322,2024-09-22T13:50:45.603220-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
1132,1727038252.92264,2024-09-22T13:50:52.922640-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
1162,1727038267.53891,2024-09-22T13:51:07.538910-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"

Received some more (null) transitions and restarts

1272,1727038591.74358,2024-09-22T13:56:31.743580-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
1431,1727038599.1122,2024-09-22T13:56:39.112200-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
1620,1727038892.42846,2024-09-22T14:01:32.428460-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
1898,1727038899.855,2024-09-22T14:01:39.855000-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
1973,1727039193.41537,2024-09-22T14:06:33.415370-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
2251,1727039200.84957,2024-09-22T14:06:40.849570-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

Until we received a VISIT_STARTED and ended the trip

2320,1727039501.05106,2024-09-22T14:11:41.051060-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
2323,1727039501.05468,2024-09-22T14:11:41.054680-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
2346,1727039502.19317,2024-09-22T14:11:42.193170-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
2348,1727039502.27354,2024-09-22T14:11:42.273540-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
We then started another trip almost immediately and saw the same pattern (14:11 to 14:40)
2681,1727039509.94628,2024-09-22T14:11:49.946280-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
2722,1727039996.37168,2024-09-22T14:19:56.371680-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
2725,1727039996.45941,2024-09-22T14:19:56.459410-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
2733,1727039996.48742,2024-09-22T14:19:56.487420-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
2736,1727039996.49355,2024-09-22T14:19:56.493550-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
2739,1727039996.49944,2024-09-22T14:19:56.499440-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
2742,1727039996.50447,2024-09-22T14:19:56.504470-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
2912,1727040003.79593,2024-09-22T14:20:03.795930-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

Multiple (null) and restart transitions

3103,1727040205.48435,2024-09-22T14:23:25.484350-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
3217,1727040212.8607,2024-09-22T14:23:32.860700-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
3443,1727040527.41087,2024-09-22T14:28:47.410870-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
3454,1727040528.01418,2024-09-22T14:28:48.014180-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
3745,1727040535.71158,2024-09-22T14:28:55.711580-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

Until we got another VISIT started and end the trip

3804,1727041215.81543,2024-09-22T14:40:15.815430-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
3807,1727041215.8206,2024-09-22T14:40:15.820600-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
3828,1727041216.99725,2024-09-22T14:40:16.997250-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
3832,1727041217.08601,2024-09-22T14:40:17.086010-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
3834,1727041217.09226,2024-09-22T14:40:17.092260-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
3857,1727041217.13321,2024-09-22T14:40:17.133210-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
3983,1727041219.39715,2024-09-22T14:40:19.397150-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
We then get another geofence exit almost immediately and see the same pattern from 14:41 to 14:52
4504,1727041302.19559,2024-09-22T14:41:42.195590-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
4507,1727041302.20887,2024-09-22T14:41:42.208870-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
4515,1727041302.23276,2024-09-22T14:41:42.232760-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
4518,1727041302.23638,2024-09-22T14:41:42.236380-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

and then a VISIT transition and multiple RESTARTS

4569,1727041564.60578,2024-09-22T14:46:04.605780-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
4582,1727041565.14721,2024-09-22T14:46:05.147210-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
4887,1727041572.56299,2024-09-22T14:46:12.562990-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
4959,1727041811.53994,2024-09-22T14:50:11.539940-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
5260,1727041819.00987,2024-09-22T14:50:19.009870-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

until we get a trip end

5319,1727041923.14004,2024-09-22T14:52:03.140040-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
5322,1727041923.14419,2024-09-22T14:52:03.144190-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
5343,1727041924.20322,2024-09-22T14:52:04.203220-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
5345,1727041924.28274,2024-09-22T14:52:04.282740-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
5368,1727041924.33299,2024-09-22T14:52:04.332990-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_WAITING_FOR_TRIP_START"
5371,1727041924.337,2024-09-22T14:52:04.337000-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
Similar pattern from 14:57 to 15:03
5728,1727042254.49824,2024-09-22T14:57:34.498240-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
5731,1727042254.50326,2024-09-22T14:57:34.503260-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
5739,1727042254.57636,2024-09-22T14:57:34.576360-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
5742,1727042254.5796,2024-09-22T14:57:34.579600-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
5749,1727042255.1894,2024-09-22T14:57:35.189400-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
6068,1727042262.52297,2024-09-22T14:57:42.522970-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
6135,1727042611.85548,2024-09-22T15:03:31.855480-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
6138,1727042611.85906,2024-09-22T15:03:31.859060-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
6161,1727042613.08628,2024-09-22T15:03:33.086280-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
6163,1727042613.1656,2024-09-22T15:03:33.165600-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
6186,1727042613.19349,2024-09-22T15:03:33.193490-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_WAITING_FOR_TRIP_START"
6193,1727042613.20001,2024-09-22T15:03:33.200010-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
6196,1727042613.2055,2024-09-22T15:03:33.205500-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
6364,1727042615.18936,2024-09-22T15:03:35.189360-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
6492,1727042619.92129,2024-09-22T15:03:39.921290-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
And one more from 15:22 to 15:57
6529,1727043758.77261,2024-09-22T15:22:38.772610-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
6532,1727043758.77971,2024-09-22T15:22:38.779710-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
6540,1727043758.86408,2024-09-22T15:22:38.864080-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
6543,1727043758.86705,2024-09-22T15:22:38.867050-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
6551,1727043759.48587,2024-09-22T15:22:39.485870-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
6723,1727043766.74084,2024-09-22T15:22:46.740840-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
6914,1727045172.11259,2024-09-22T15:46:12.112590-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
7208,1727045179.5363,2024-09-22T15:46:19.536300-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
7224,1727045186.17217,2024-09-22T15:46:26.172170-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
7296,1727045544.21688,2024-09-22T15:52:24.216880-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
7467,1727045551.74206,2024-09-22T15:52:31.742060-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
7663,1727045848.25977,2024-09-22T15:57:28.259770-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
7953,1727045855.91084,2024-09-22T15:57:35.910840-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
7966,1727045865.68875,2024-09-22T15:57:45.688750-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
7969,1727045865.69871,2024-09-22T15:57:45.698710-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
7982,1727045866.23967,2024-09-22T15:57:46.239670-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
7984,1727045866.24866,2024-09-22T15:57:46.248660-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
8011,1727045866.29975,2024-09-22T15:57:46.299750-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"

The next exit was a substantial time away so is not part of this fragmented trip.

8401,1727049760.00312,2024-09-22T17:02:40.003120-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"

@shankari
Copy link
Contributor Author

There are 5 clusters of points in the map, and 5 trip segments in the logs. So the first order of business is to look at why we are ending the trips so many times.

@JGreenlee for visibility

@shankari
Copy link
Contributor Author

We are ending trips because of the VISIT transitions

2320,1727039501.05106,2024-09-22T14:11:41.051060-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
2323,1727039501.05468,2024-09-22T14:11:41.054680-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
2346,1727039502.19317,2024-09-22T14:11:42.193170-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
2348,1727039502.27354,2024-09-22T14:11:42.273540-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"

Looking at the logs around that

2316,1727039501.04798,2024-09-22T14:11:41.047980-07:00,"Received visit notification = <+45.51667792,-122.65693038> +/- 59.58m (2024-09-22 21:06:47 +0000 to -) (null)"
2319,1727039501.05051,2024-09-22T14:11:41.050510-07:00,"departure date is 4001-01-01 00:00:00 +0000, isDistantDate? 1, after distantDate? 0 "
2320,1727039501.05106,2024-09-22T14:11:41.051060-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
2321,1727039501.05311,2024-09-22T14:11:41.053110-07:00,Checking invalid visit started transition...
2322,1727039501.05415,2024-09-22T14:11:41.054150-07:00,"visit started transition is not invalid, returning false"

We do check for invalid visit started transitions here:
https://github.com/e-mission/e-mission-data-collection/blob/06a90be0db66402b13bd6c01e5676936857c2f04/src/ios/Location/TripDiaryStateMachine.m#L600

However, in this case, neither check was successful. Because of the restarts, there were multiple transitions. And the last two transitions were

1973,1727039193.41537,2024-09-22T14:06:33.415370-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
2251,1727039200.84957,2024-09-22T14:06:40.849570-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
2320,1727039501.05106,2024-09-22T14:11:41.051060-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"

So we didn't even check for the deltaTs.

And even if we had found the correct transitions and checked for the deltaTs, it would have been more than a few minutes.
This really does not seem like a spurious visit transition - it was sufficiently after the trip start that it seems meaningful.

1162,1727038267.53891,2024-09-22T13:51:07.538910-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
2320,1727039501.05106,2024-09-22T14:11:41.051060-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"

@shankari
Copy link
Contributor Author

The visit API is a black box, so we are not able to look into it or understand why it is generating these spurious visit transitions.
All we can try to do at this point is to add additional checks that detect that the visit transition was invalid and ignore it.

Since the transition here was several minutes after the trip start, the only possible check would be that the user was still moving - i.e. that we were receiving location updates that represented movement consistently. If so, we can ignore the VISIT_STARTED notifications.

@shankari
Copy link
Contributor Author

Looking at the location logs, it looks like this won't really work. The last log statement before the VISIT_STARTED transition was from 14:07

2300,1727039233.09842,2024-09-22T14:07:13.098420-07:00,"Recieved location <+45.51682256,-122.65781566> +/- 2.53m (speed 4.99 mps / course 180.06) @ 9/22/24, 2:07:13 PM Pacific Daylight Time, ongoing trip = true"

2320,1727039501.05106,2024-09-22T14:11:41.051060-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"

Verified using uploaded data

We get data around 14:07 and then nothing else until 14:11
>>> loc_df.query("local_dt_year == 2024 & local_dt_month == 9 & local_dt_day == 22 & local_dt_hour == 14 & local_dt_minute == 7").fmt_time
18421    2024-09-22T14:07:00.999649-07:00
18422    2024-09-22T14:07:01.999648-07:00
18423    2024-09-22T14:07:02.999645-07:00
18424    2024-09-22T14:07:03.999644-07:00
18425    2024-09-22T14:07:04.999643-07:00
18426    2024-09-22T14:07:05.999641-07:00
18427    2024-09-22T14:07:06.999640-07:00
18428    2024-09-22T14:07:07.999639-07:00
18429    2024-09-22T14:07:08.999639-07:00
18430    2024-09-22T14:07:09.999637-07:00
18431    2024-09-22T14:07:10.999637-07:00
18432    2024-09-22T14:07:11.999637-07:00
18433    2024-09-22T14:07:12.999636-07:00
Name: fmt_time, dtype: object

>>> loc_df.query("local_dt_year == 2024 & local_dt_month == 9 & local_dt_day == 22 & local_dt_hour == 14 & local_dt_minute == 8").fmt_time
Series([], Name: fmt_time, dtype: object)
>>> loc_df.query("local_dt_year == 2024 & local_dt_month == 9 & local_dt_day == 22 & local_dt_hour == 14 & local_dt_minute == 9").fmt_time
Series([], Name: fmt_time, dtype: object)
>>> loc_df.query("local_dt_year == 2024 & local_dt_month == 9 & local_dt_day == 22 & local_dt_hour == 14 & local_dt_minute == 10").fmt_time
Series([], Name: fmt_time, dtype: object)

>>> loc_df.query("local_dt_year == 2024 & local_dt_month == 9 & local_dt_day == 22 & local_dt_hour == 14 & local_dt_minute == 11").fmt_time
18435    2024-09-22T14:11:40.653219-07:00
18436    2024-09-22T14:11:40.845128-07:00
18437    2024-09-22T14:11:41.001462-07:00
Name: fmt_time, dtype: object

@shankari
Copy link
Contributor Author

Let's see what is happening between 14:07 and 14:11 in the logs.
Nothing.

We get the last location input that we see, and then we don't see any other logs until we initialize the plugins as part of restarting the app, just before we receive the VISIT transition.

2300,1727039233.09842,2024-09-22T14:07:13.098420-07:00,"Recieved location <+45.51682256,-122.65781566> +/- 2.53m (speed 4.99 mps / course 180.06) @ 9/22/24, 2:07:13 PM Pacific Daylight Time, ongoing trip = true"
2301,1727039500.42191,2024-09-22T14:11:40.421910-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
2302,1727039500.42901,2024-09-22T14:11:40.429010-07:00,"intro_done result = {
    ""intro_done"" = ""2024-08-28T09:57:43.879-07:00"";
}"
2303,1727039500.43044,2024-09-22T14:11:40.430440-07:00,"Auth found in local storage, now it should be stable"
2304,1727039500.43115,2024-09-22T14:11:40.431150-07:00,finished init of iOS native code
2311,1727039500.99902,2024-09-22T14:11:40.999020-07:00,started fine location tracking with accuracy = -2 and distanceFilter = 1

With these logs, and the iOS distance filter, it is not 100% clear whether:

  1. we weren't getting locations because the user had stopped moving (because of the distance filter)
  2. we weren't getting locations because the app had been killed, and the app was re-launched to deliver the visit notification

Given that we see the pluginInitialize messages, (2) seems more likely.

But it would be good to get some indication from the user whether they actually did stop moving at that time. Because, we do try to detect when the app has been terminated, and I don't see that log either.
https://github.com/e-mission/e-mission-data-collection/blob/06a90be0db66402b13bd6c01e5676936857c2f04/src/ios/BEMAppDelegate.m#L103

@shankari
Copy link
Contributor Author

Poking around a bit more at the termination, note (from https://developer.apple.com/documentation/corelocation/cllocationmanager/startupdatinglocation())
that

If you start this service and your app is suspended, the system stops the delivery of events until your app starts running again (either in the foreground or background). If your app is terminated, the delivery of new location events stops altogether. Therefore, if your app needs to receive location events while in the background, it must include the UIBackgroundModes key (with the location value) in its Info.plist file.

We do have the UIBackgroundModes key set https://github.com/e-mission/e-mission-data-collection/blob/06a90be0db66402b13bd6c01e5676936857c2f04/plugin.xml#L206 so the app should be running in the background.

But while the background modes protect the app from being terminated because it went off the foreground, it clearly does not prevent it from being terminated due to resource constraints.

Looking at documentation around termination:
https://developer.apple.com/documentation/xcode/reduce-terminations-in-your-app
it looks like we can view termination reasons in Xcode, or use the new MetricKit (available in iOS 13+).

We now require a minimum of iOS 13+ so that is definitely an option.

@shankari
Copy link
Contributor Author

Checked the organizer - it does not have enough metrics. Which seems to argue against the reason being termination if this is consistent behavior for Nathan and Joe.

Screenshot 2024-10-23 at 6 29 18 PM

Note also that, although we noticed that there was a restart around the time we had no locations, we also had multiple restarts that were not correlated with lack of locations.

Focusing on the transitions:

844,1727038244.96454,2024-09-22T13:50:44.964540-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
847,1727038244.96749,2024-09-22T13:50:44.967490-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
856,1727038245.60322,2024-09-22T13:50:45.603220-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
1132,1727038252.92264,2024-09-22T13:50:52.922640-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
1162,1727038267.53891,2024-09-22T13:51:07.538910-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
1272,1727038591.74358,2024-09-22T13:56:31.743580-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
1431,1727038599.1122,2024-09-22T13:56:39.112200-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
1620,1727038892.42846,2024-09-22T14:01:32.428460-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
1898,1727038899.855,2024-09-22T14:01:39.855000-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

Checking the location logs around those, we see that there seem to be pauses for ~ 5 minutes, followed by reinitializing, and then seeing locations again

1244,1727038321.09963,2024-09-22T13:52:01.099630-07:00,"Recieved location <+45.49754485,-122.60493378> +/- 2.14m (speed 14.43 mps / course 270.27) @ 9/22/24, 1:52:00 PM Pacific Daylight Time, ongoing trip = true"


1245,1727038590.47854,2024-09-22T13:56:30.478540-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
1246,1727038590.48451,2024-09-22T13:56:30.484510-07:00,"intro_done result = {
    ""intro_done"" = ""2024-08-28T09:57:43.879-07:00"";
}"
1247,1727038590.48536,2024-09-22T13:56:30.485360-07:00,"Auth found in local storage, now it should be stable"

1265,1727038591.13447,2024-09-22T13:56:31.134470-07:00,"Recieved location <+45.49730524,-122.62361088> +/- 2.01m (speed 14.08 mps / course 263.37) @ 9/22/24, 1:56:30 PM Pacific Daylight Time, ongoing trip = true"
1267,1727038591.64683,2024-09-22T13:56:31.646830-07:00,"Recieved location <+45.49729159,-122.62379686> +/- 2.25m (speed 14.58 mps / course 263.05) @ 9/22/24, 1:56:31 PM Pacific Daylight Time, ongoing trip = true"

--------

1594,1727038631.09737,2024-09-22T13:57:11.097370-07:00,"Recieved location <+45.49683290,-122.63151200> +/- 2.00m (speed 14.95 mps / course 271.40) @ 9/22/24, 1:57:11 PM Pacific Daylight Time, ongoing trip = true"
1595,1727038891.24254,2024-09-22T14:01:31.242540-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
1605,1727038891.79792,2024-09-22T14:01:31.797920-07:00,started fine location tracking with accuracy = -2 and distanceFilter = 1

1615,1727038891.83103,2024-09-22T14:01:31.831030-07:00,"Recieved location <+45.50487549,-122.64892057> +/- 2.01m (speed 10.75 mps / course 270.39) @ 9/22/24, 2:01:31 PM Pacific Daylight Time, ongoing trip = true"
1617,1727038892.34075,2024-09-22T14:01:32.340750-07:00,"Recieved location <+45.50487412,-122.64905817> +/- 2.00m (speed 10.73 mps / course 270.39) @ 9/22/24, 2:01:32 PM Pacific Daylight Time, ongoing trip = true"

@shankari
Copy link
Contributor Author

Next steps:

  • PSU: Report whether you were moving or not during the gaps in the location data
  • Shankari: Integrate with MetricKit to see if we can get additional information on terminations
  • Shankari: Add an option to remove the distance filter completely aka use kCLDistanceFilterNone so that we can experiment with no distance filter to collect data even when the user is not moving, although it may result in higher battery drain
    https://developer.apple.com/documentation/corelocation/kcldistancefilternone?language=objc

@shankari
Copy link
Contributor Author

One other observation from the logs before I forget.

I noticed that there were several UI logs that were overlapping with the start of this trip

e.g.

833,1727038244.95052,2024-09-22T13:50:44.950520-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
836,1727038244.95445,2024-09-22T13:50:44.954450-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
844,1727038244.96454,2024-09-22T13:50:44.964540-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
847,1727038244.96749,2024-09-22T13:50:44.967490-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

but then

1372,1727038592.89993,2024-09-22T13:56:32.899930-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//datastreams/find_entries/timestamp
1385,1727038594.04323,2024-09-22T13:56:34.043230-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//datastreams/find_entries/timestamp
...

The UI load seems to have started at around

929,1727038246.42178,2024-09-22T13:50:46.421780-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//pipeline/get_range_ts
937,1727038246.43513,2024-09-22T13:50:46.435130-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//profile/update
948,1727038246.4863,2024-09-22T13:50:46.486300-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//profile/update
955,1727038246.96463,2024-09-22T13:50:46.964630-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//datastreams/find_entries/timestamp
...
1007,1727038248.78387,2024-09-22T13:50:48.783870-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//datastreams/find_entries/timestamp


1330,1727038592.50981,2024-09-22T13:56:32.509810-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//pipeline/get_range_ts
1354,1727038592.54016,2024-09-22T13:56:32.540160-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//profile/update
1367,1727038592.88539,2024-09-22T13:56:32.885390-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//datastreams/find_entries/timestamp
...
1419,1727038594.70805,2024-09-22T13:56:34.708050-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//datastreams/find_entries/timestamp

1679,1727038892.86086,2024-09-22T14:01:32.860860-07:00,postToHost called with url = https://open-access-openpath.nrel.gov/api//pipeline/get_range_ts

and if we look at the periods where the app appeared to restart, we were still loading data when the app appeared to be terminated.

1240,1727038318.74052,2024-09-22T13:51:58.740520-07:00,"fetchNominatimLocName: found cached response for -122.60380015564107,45.503289315482654"
1241,1727038319.10062,2024-09-22T13:51:59.100620-07:00,"Recieved location <+45.49754129,-122.60456163> +/- 2.01m (speed 14.13 mps / course 270.00) @ 9/22/24, 1:51:58 PM Pacific Daylight Time, ongoing trip = true"
1242,1727038320.0978,2024-09-22T13:52:00.097800-07:00,"Recieved location <+45.49753932,-122.60475056> +/- 2.00m (speed 14.58 mps / course 270.27) @ 9/22/24, 1:51:59 PM Pacific Daylight Time, ongoing trip = true"
1243,1727038320.74276,2024-09-22T13:52:00.742760-07:00,"fetchNominatimLocName: found cached response for -122.68062146450143,45.510185801655595"
1244,1727038321.09963,2024-09-22T13:52:01.099630-07:00,"Recieved location <+45.49754485,-122.60493378> +/- 2.14m (speed 14.43 mps / course 270.27) @ 9/22/24, 1:52:00 PM Pacific Daylight Time, ongoing trip = true"

1245,1727038590.47854,2024-09-22T13:56:30.478540-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

@JGreenlee I wonder if this is due to the fact that we load data on every resume now.

If we are getting terminated due to resource constraints, the problem may be:

  • app is launched to receive geofence exit
  • app begins pulling data from the server
  • there are a lot of trips, so we end up with a lot of CPU/memory usage, more than the OS likes to see for a background app
  • app is terminated
  • app is launched to receive location/visit notification
  • app begins pulling data from the server
  • high resource usage
  • app is terminated
  • app begins pulling data
  • high resource usage
  • app is terminated
    infinite cycle

I would guess that this doesn't trigger for the test phone because it is not running anything else (so the resources are not constrained) and there aren't a lot of recent trips anyway since I don't carry the test phone everywhere.

It seems like a general optimization would be to not load the diary if the app has been launched in the background since nobody is watching anyway. Need to see if the suspend/resume/launch notifications let us determine whether the launch was in the foreground or the background.

@JGreenlee
Copy link

I am surprised that the webview is even able to run while the app is not in the foreground. (I am guessing this iOS-specific because I don't think it would be possible on Android.)

It seems like a general optimization would be to not load the diary if the app has been launched in the background since nobody is watching anyway.

We certainly do not want to be loading the diary when in the background – especially because when the app is resumed from the background, it will all be reloaded again anyway.

Need to see if the suspend/resume/launch notifications let us determine whether the launch was in the foreground or the background.

Yes it is possible via React Native's AppState API https://reactnative.dev/docs/0.71/appstate
Currently, we use this to determine when the app is resumed from the background (state transitions to active).
However, we don't check AppState on a cold launch.

@shankari
Copy link
Contributor Author

I am surprised that the webview is even able to run while the app is not in the foreground. (I am guessing this iOS-specific because I don't think it would be possible on Android.)

Yes, on iOS, the webview keeps running even when the app is in the background. For the trip-end notifications, this was actually helpful, here it is annoying 😄

@shankari
Copy link
Contributor Author

wrt (1) from #1095 (comment)

PSU also reported this trip (to a concert at around 5pm, returning at around 9:15pm). This was a freeway car trip, but still has clusters of location points.
another_trip

This seems to argue for the app termination as the cause of the issue.
Let's see if this is borne out by the logs.

The relevant transitions, clustered by trip start and end are:
8401,1727049760.00312,2024-09-22T17:02:40.003120-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
8404,1727049760.00759,2024-09-22T17:02:40.007590-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
8727,1727049779.21446,2024-09-22T17:02:59.214460-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"

8836,1727050091.60347,2024-09-22T17:08:11.603470-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
8864,1727050092.74383,2024-09-22T17:08:12.743830-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"

9227,1727050348.57365,2024-09-22T17:12:28.573650-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
9230,1727050348.57728,2024-09-22T17:12:28.577280-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
9615,1727050470.746,2024-09-22T17:14:30.746000-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"

9947,1727050496.23074,2024-09-22T17:14:56.230740-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
9965,1727050496.86823,2024-09-22T17:14:56.868230-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"

10049,1727051839.31144,2024-09-22T17:37:19.311440-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
10057,1727051839.32109,2024-09-22T17:37:19.321090-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
10384,1727051850.72649,2024-09-22T17:37:30.726490-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"

10442,1727051958.0769,2024-09-22T17:39:18.076900-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
10614,1727051965.46312,2024-09-22T17:39:25.463120-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
10814,1727052259.73927,2024-09-22T17:44:19.739270-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
11135,1727052267.17325,2024-09-22T17:44:27.173250-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
11183,1727052634.01929,2024-09-22T17:50:34.019290-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
11494,1727052641.68046,2024-09-22T17:50:41.680460-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
11570,1727053061.32576,2024-09-22T17:57:41.325760-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
11879,1727053068.78947,2024-09-22T17:57:48.789470-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
11953,1727053487.29451,2024-09-22T18:04:47.294510-07:00,"In TripDiaryStateMachine, received transition (null) in state STATE_ONGOING_TRIP"
12243,1727053494.68704,2024-09-22T18:04:54.687040-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

12306,1727054400.92327,2024-09-22T18:20:00.923270-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
12332,1727054402.07335,2024-09-22T18:20:02.073350-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"

Checking for app initializations and the resulting gaps...

8816,1727049838.10128,2024-09-22T17:03:58.101280-07:00,"Recieved location <+45.50474626,-122.59560767> +/- 2.78m (speed 3.78 mps / course 180.33) @ 9/22/24, 5:03:58 PM Pacific Daylight Time, ongoing trip = true"
8817,1727050091.01988,2024-09-22T17:08:11.019880-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler


9207,1727050130.50191,2024-09-22T17:08:50.501910-07:00,"fetchNominatimLocName: found cached response for -122.68484588612836,45.51198358872893"
9208,1727050347.98091,2024-09-22T17:12:27.980910-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

9595,1727050388.09028,2024-09-22T17:13:08.090280-07:00,"Recieved location <+45.50346983,-122.60115508> +/- 7.03m (speed 1.73 mps / course 269.46) @ 9/22/24, 5:13:08 PM Pacific Daylight Time, ongoing trip = true"
9596,1727050470.3259,2024-09-22T17:14:30.325900-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler


10026,1727050527.48688,2024-09-22T17:15:27.486880-07:00,"fetchNominatimLocName: found cached response for -122.60459325007982,45.50510568385012"
10027,1727051838.68285,2024-09-22T17:37:18.682850-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

10414,1727051877.80052,2024-09-22T17:37:57.800520-07:00,"Recieved location <+45.50532311,-122.60209670> +/- 8.39m (speed 0.00 mps / course -1.00) @ 9/22/24, 5:37:57 PM Pacific Daylight Time, ongoing trip = true"
10417,1727051957.08021,2024-09-22T17:39:17.080210-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

10789,1727051998.08678,2024-09-22T17:39:58.086780-07:00,"Recieved location <+45.51340469,-122.60188446> +/- 4.75m (speed 12.45 mps / course 358.87) @ 9/22/24, 5:39:58 PM Pacific Daylight Time, ongoing trip = true"
10790,1727052258.37167,2024-09-22T17:44:18.371670-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

11154,1727052295.09113,2024-09-22T17:44:55.091130-07:00,"Recieved location <+45.52663990,-122.60173726> +/- 2.00m (speed 0.03 mps / course -1.00) @ 9/22/24, 5:44:55 PM Pacific Daylight Time, ongoing trip = true"
11157,1727052299.23605,2024-09-22T17:44:59.236050-07:00,"fetchNominatimLocName: found cached response for -122.68103460785501,45.50997720921216"
11158,1727052632.89464,2024-09-22T17:50:32.894640-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

11542,1727052673.09141,2024-09-22T17:51:13.091410-07:00,"Recieved location <+45.53133050,-122.57167131> +/- 6.10m (speed 24.67 mps / course 95.16) @ 9/22/24, 5:51:13 PM Pacific Daylight Time, ongoing trip = true"
11543,1727052673.36592,2024-09-22T17:51:13.365920-07:00,"fetchNominatimLocName: found cached response for -122.6037568685487,45.50329662665371"
11544,1727053060.35611,2024-09-22T17:57:40.356110-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

11925,1727053099.8188,2024-09-22T17:58:19.818800-07:00,"fetchNominatimLocName: found cached response for -122.68103460785501,45.50997720921216"
11927,1727053101.09287,2024-09-22T17:58:21.092870-07:00,"Recieved location <+45.54131212,-122.43677084> +/- 4.16m (speed 30.89 mps / course 69.99) @ 9/22/24, 5:58:21 PM Pacific Daylight Time, ongoing trip = true"
11928,1727053486.09417,2024-09-22T18:04:46.094170-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

12284,1727053525.7298,2024-09-22T18:05:25.729800-07:00,"fetchNominatimLocName: found cached response for -122.68484588612836,45.51198358872893"
12286,1727053527.09336,2024-09-22T18:05:27.093360-07:00,"Recieved location <+45.53871970,-122.40473756> +/- 2.00m (speed 1.51 mps / course 145.72) @ 9/22/24, 6:05:26 PM Pacific Daylight Time, ongoing trip = true"
12287,1727054400.31329,2024-09-22T18:20:00.313290-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

12672,1727054414.94312,2024-09-22T18:20:14.943120-07:00,Reading trip's 65 location points at Sun Sep 22 2024 18:20:14 GMT-0700 (Pacific Daylight Time)
12689,1727054441.82164,2024-09-22T18:20:41.821640-07:00,"fetchNominatimLocName: found cached response for -122.6037568685487,45.50329662665371"
12690,1727064280.32725,2024-09-22T21:04:40.327250-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

Interleaving them, we get

Time Delta from prev line, rounded to 15 sec What happened Logs
17:02:40 NA Trip started 8401,1727049760.00312,2024-09-22T17:02:40.003120-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
17:03:53 + 1 Last location point, app crashed? 8816,1727049838.10128,2024-09-22T17:03:58.101280-07:00,"Recieved location <+45.50474626,-122.59560767> +/- 2.78m (speed 3.78 mps / course 180.33) @ 9/22/24, 5:03:58 PM Pacific Daylight Time, ongoing trip = true"
17:08:11 + 4:30 App initialized 8817,1727050091.01988,2024-09-22T17:08:11.019880-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
17:08:11 0 Trip ended 8836,1727050091.60347,2024-09-22T17:08:11.603470-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
17:12:28 + 4:20 Trip started 179227,1727050348.57365,2024-09-22T17:12:28.573650-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
17:13:08 + 1 Last location point 9595,1727050388.09028,2024-09-22T17:13:08.090280-07:00,"Recieved location <+45.50346983,-122.60115508> +/- 7.03m (speed 1.73 mps / course 269.46) @ 9/22/24, 5:13:08 PM Pacific Daylight Time, ongoing trip = true"
17:14:30 +1:20 App initialized 9596,1727050470.3259,2024-09-22T17:14:30.325900-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
17:14:56 + 4:20 Trip ended 9947,1727050496.23074,2024-09-22T17:14:56.230740-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
17:37:19 + 24:00 Trip started 10049,1727051839.31144,2024-09-22T17:37:19.311440-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
17:37:57 + 00:30 Last location point 10414,1727051877.80052,2024-09-22T17:37:57.800520-07:00,"Recieved location <+45.50532311,-122.60209670> +/- 8.39m (speed 0.00 mps / course -1.00) @ 9/22/24, 5:37:57 PM Pacific Daylight Time, ongoing trip = true"
17:39:17 + 01:30 App initialize 10417,1727051957.08021,2024-09-22T17:39:17.080210-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
17:39:58 +00:30 Last location point 10789,1727051998.08678,2024-09-22T17:39:58.086780-07:00,"Recieved location <+45.51340469,-122.60188446> +/- 4.75m (speed 12.45 mps / course 358.87) @ 9/22/24, 5:39:58 PM Pacific Daylight Time, ongoing trip = true"
17:44:18 +04:30 App initialize 10790,1727052258.37167,2024-09-22T17:44:18.371670-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
17:44:55 +00:30 Last location point 11154,1727052295.09113,2024-09-22T17:44:55.091130-07:00,"Recieved location <+45.52663990,-122.60173726> +/- 2.00m (speed 0.03 mps / course -1.00) @ 9/22/24, 5:44:55 PM Pacific Daylight Time, ongoing trip = true"
17:50:32 +04:30 App Initialize 11158,1727052632.89464,2024-09-22T17:50:32.894640-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
17:51:13 +00:45 Last location point 11542,1727052673.09141,2024-09-22T17:51:13.091410-07:00,"Recieved location <+45.53133050,-122.57167131> +/- 6.10m (speed 24.67 mps / course 95.16) @ 9/22/24, 5:51:13 PM Pacific Daylight Time, ongoing trip = true"
17:57:40 +06:30 App initialize 11544,1727053060.35611,2024-09-22T17:57:40.356110-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
17:58:21 +00:45 Last location point 11927,1727053101.09287,2024-09-22T17:58:21.092870-07:00,"Recieved location <+45.54131212,-122.43677084> +/- 4.16m (speed 30.89 mps / course 69.99) @ 9/22/24, 5:58:21 PM Pacific Daylight Time, ongoing trip = true"
18:04:46 +06:30 App initialize 11928,1727053486.09417,2024-09-22T18:04:46.094170-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
18:05:27 +00:45 Last location 12286,1727053527.09336,2024-09-22T18:05:27.093360-07:00,"Recieved location <+45.53871970,-122.40473756> +/- 2.00m (speed 1.51 mps / course 145.72) @ 9/22/24, 6:05:26 PM Pacific Daylight Time, ongoing trip = true"
18:20:00 +14:30 App initialize 12287,1727054400.31329,2024-09-22T18:20:00.313290-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
18:20:00 + 0 trip end 12306,1727054400.92327,2024-09-22T18:20:00.923270-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"

Two main takeaways from that deep dive:

  • The VISIT transitions are not related to the app restarts; we see many app restarts between 17:37:19 and 18:20:00 without a VISIT transition
  • We do appear to get spurious VISIT transitions during trips (maybe at stop lights?). If we fix the restart/missing location issue, we are likely to be able to detect that they are spurious and ignore them.

@shankari
Copy link
Contributor Author

shankari commented Oct 27, 2024

Testing out the change, I see

23258,1729999919.70029,2024-10-26T20:31:59.700290-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"

23269,1729999919.9377,2024-10-26T20:31:59.937700-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
23270,1729999920.02693,2024-10-26T20:32:00.026930-07:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 2 (outside)
23271,1729999920.0396,2024-10-26T20:32:00.039600-07:00,Received OUTSIDE geofence state when currState = STATE_ONGOING_TRIP
23272,1729999920.05051,2024-10-26T20:32:00.050510-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"

23798,1730000557.73419,2024-10-26T20:42:37.734190-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
23801,1730000558.04736,2024-10-26T20:42:38.047360-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
23814,1730000559.35952,2024-10-26T20:42:39.359520-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
23817,1730000559.45782,2024-10-26T20:42:39.457820-07:00,Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START


23859,1730000868.93481,2024-10-26T20:47:48.934810-07:00,Application will enter the foreground

23860,1730000869.03664,2024-10-26T20:47:49.036640-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1730000868.919,""reading"":""active"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"
23861,1730000869.05134,2024-10-26T20:47:49.051340-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1730000868.925,""reading"":""active"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"
The full history (egrep "2024-10-26.*(app_state_change|pluginInitialize|T_TRIP_STARTED|T_TRIP_END_DETECTED)" /tmp/loggerDB.txt.withdate.log) across the day shows a very similar pattern
19979,1729956974.70075,2024-10-26T08:36:14.700750-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler

20211,1729956984.49204,2024-10-26T08:36:24.492040-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1729956984.49,""reading"":""background"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"
20212,1729956984.50552,2024-10-26T08:36:24.505520-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1729956984.49,""reading"":""background"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"

20217,1729957924.44903,2024-10-26T08:52:04.449030-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
21375,1729959147.31062,2024-10-26T09:12:27.310620-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"

21444,1729962183.24747,2024-10-26T10:03:03.247470-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
22137,1729962951.54789,2024-10-26T10:15:51.547890-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"

22192,1729996352.23529,2024-10-26T19:32:32.235290-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
23207,1729997962.54596,2024-10-26T19:59:22.545960-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"

23261,1729999919.795,2024-10-26T20:31:59.795000-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
23801,1730000558.04736,2024-10-26T20:42:38.047360-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"

23860,1730000869.03664,2024-10-26T20:47:49.036640-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1730000868.919,""reading"":""active"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"
24109,1730000891.25726,2024-10-26T20:48:11.257260-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1730000891.244,""reading"":""background"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"
24113,1730005284.58868,2024-10-26T22:01:24.588680-07:00,"addStatReading: adding CLIENT_TIME event: {""name"":""app_state_change"",""ts"":1730005284.486,""reading"":""active"",""client_app_version"":""1.9.4"",""client_os_version"":""15.7.5""}"

Looks promising; let's push it out to production and see if our partners at PSU are able to reproduce the original issue.

@shankari
Copy link
Contributor Author

shankari commented Nov 6, 2024

Pushed it out to production after some delays. However, PSU reported that they were still seeing gaps in the reported locations. Checking the logs, we see that the app is no longer crashing, but there are arbitrary 5 minute gaps in the data collection.

In some cases, the speed is low

29578,1730822372.89939,2024-11-05T07:59:32.899390-08:00,"Recieved location <...> +/- 13.93m (speed 1.36 mps / course -1.00) @ 11/5/24, 7:59:32 AM Pacific Standard Time, ongoing trip = true"
29579,1730823787.73012,2024-11-05T08:23:07.730120-08:00,"Recieved location <...> +/- 12.41m (speed 1.36 mps / course -1.00) @ 11/5/24, 7:59:33 AM Pacific Standard Time, ongoing trip = true"

But in a lot of cases it is not. The app is clearly not restarting (no pluginInitialize); iOS just decides to not stop giving us location points for a while.

29621,1730823829.09617,2024-11-05T08:23:49.096170-08:00,"Recieved location <...> +/- 3.67m (speed 4.46 mps / course 270.71) @ 11/5/24, 8:23:49 AM Pacific Standard Time, ongoing trip = true"
29622,1730823961.2628,2024-11-05T08:26:01.262800-08:00,"Recieved location <...> +/- 29.74m (speed -1.00 mps / course -1.00) @ 11/5/24, 8:26:01 AM Pacific Standard Time, ongoing trip = true"

29661,1730824002.09654,2024-11-05T08:26:42.096540-08:00,"Recieved location <...> +/- 6.48m (speed 4.52 mps / course 269.90) @ 11/5/24, 8:26:42 AM Pacific Standard Time, ongoing trip = true"
29665,1730824262.14861,2024-11-05T08:31:02.148610-08:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_ONGOING_TRIP"

29676,1730824272.09609,2024-11-05T08:31:12.096090-08:00,"Recieved location <...> +/- 5.74m (speed 4.89 mps / course 265.95) @ 11/5/24, 8:31:12 AM Pacific Standard Time, ongoing trip = true"
29677,1730824563.13458,2024-11-05T08:36:03.134580-08:00,"Recieved location <...> +/- 5.58m (speed 6.02 mps / course 268.36) @ 11/5/24, 8:36:03 AM Pacific Standard Time, ongoing trip = true"

Let us see if we see similar behavior on the test phone. It would help a lot if we are able to reproduce; we may need to look at the phone logs instead of only the app logs.

@shankari
Copy link
Contributor Author

shankari commented Nov 6, 2024

Alas, this is not reproducible on my test iphone. I plotted the trajectories from one of my trips, and we can even see the difference between two separate trips along the same major street.

Screenshot 2024-11-05 at 10 50 16 PM

@shankari
Copy link
Contributor Author

shankari commented Nov 6, 2024

Given that the OS throttling the points that we get, the most likely culprit is a different version of the OS

Checking the logs, it looks like my test phone is on 15.7.5 and the PSU phone is on 18.0.1. I am not able to find any highlighted changes to location services between iOS 15 and iOS 18.

I think we have two potential next steps:

  • see if anybody else at NREL has a test phone that is on 18+ and whether it is able to reproduce this behavior.
    • This would significantly help with debugging since we don't have to wait for logs from PSU and can see phone logs in addition to app logs
  • turn off the distance filter completely to see if it is the problem (probably not but doesn't hurt to check, particularly if we can reproduce)

@shankari
Copy link
Contributor Author

shankari commented Nov 6, 2024

Just to make doubly sure, we do set everything that is needed for the location code.

We do have allowsBackgroundLocationUpdates set

https://github.com/search?q=repo%3Ae-mission%2Fe-mission-data-collection%20allowsBackgroundLocationUpdates%20&type=code

And we listen for locationManagerDidPauseLocationUpdates and log when that happens, and I didn't see that log.

@shankari
Copy link
Contributor Author

shankari commented Nov 9, 2024

While waiting to figure out the versions of the test phones that we have, I pulled some data from a program that had predominantly iOS users. I pulled data for two days 2024-05-29 and 2024-05-31 and plotted the trajectories for a random sample of users.

The first two had perfect trajectories[1] so I was feeling fairly optimistic, and then the third one had spotty trajectories!!!
Same dates, same general physical location, same app.
Let's dig into the differences between these user phones.

[1] I also noticed that even for the good trajectories, the points were clustered together more closely off the freeway than on (aka slower speeds = closer points). Since iOS has a distance filter, this should not be the case, but I guess the phone was going fast enough that it overwhelmed the distance filter.

@shankari
Copy link
Contributor Author

shankari commented Nov 9, 2024

The three trajectories, plotted with style='.-'. Note that the lines on the first two are very thick because the points are so close together. The lines on the last are thin, because they are between isolated groups of points

user_0 user_14 user_3
Screenshot 2024-11-08 at 11 12 57 PM Screenshot 2024-11-08 at 11 14 08 PM Screenshot 2024-11-09 at 12 25 16 AM

@shankari
Copy link
Contributor Author

shankari commented Nov 9, 2024

I thought this was an almost exclusively iOS dataset, but apparently not (at least for the dates that we were testing).
When plotting the boxplot of the distances (with outliers trimmed), we see that most of the phones are actually android.
image

Let me clean up the analysis and work with a larger range of dates so that we can get a better sense of the iOS data

@shankari
Copy link
Contributor Author

shankari commented Nov 9, 2024

Cleaning up the analysis and working with the full range of dates, we get a lot more iOS users
image

It seems pretty clear that the vast majority of users have good trajectories but there are a couple (at least two) that do significantly worse. I don't see any correlation with OS version at least at this point. Some of this may be due to the geofence exit delay, so let's retry after dropping the first point of every trip.

Note also that user_14 and user_3 are both android phones, so that explains this:

I also noticed that even for the good trajectories, the points were clustered together more closely off the freeway than on (aka slower speeds = closer points). Since iOS has a distance filter, this should not be the case, but I guess the phone was going fast enough that it overwhelmed the distance filter.

@shankari
Copy link
Contributor Author

shankari commented Nov 10, 2024

It took me essentially all of yesterday to strip out the first point because I (potentially foolishly) decided to not rely on the existing segmentation output and go directly to the transitions. But I finally have it working, and the results are fairly similar.

There is one phone who seems to have non-fine-grained trips, but the majority of other phones are doing fairly well. There is more variability in the time between points, as might be expected from an OS with a distance filter - the time delta will depend on the speed.

image
image

Digging a little deeper into that phone...

@shankari
Copy link
Contributor Author

Digging into phone 6e, we see that there is significant variability across trips. There are some trips for which the trajectory data is really bad, and some for which it is better. Note that the boxplots have removed outliers because otherwise we can't see anything

image
image

Description of the median inter-point distance across trips

count     59.000000
mean      56.877464
std       99.629760
min        0.000000
25%        3.946395
50%       15.598720
75%       70.115053
max      542.875925

Again, it seems like there are some trips where the median distance between points is close to what we expect, but some where it is much larger. Let's plot a few and see if any of them show the distinctive stutter of points that PSU is seeing. And then I will have to move on to other work.

@shankari
Copy link
Contributor Author

shankari commented Nov 10, 2024

Plotting some of the trajectories as basic lines, we see that some of them do have gaps but I don't see the stutter (lots of points and then a gap) that PSU is seeing. The 90th percentile median one in particular is clearly with evenly spaced points. I do think that the points are coming in at more than 1 meter, but they seem to be fairly consistent at that distance.

Trajectories of trips whose medians are at various quantiles for the overall trip medians (all distances in meters)

Median of medians (median: 14.99 m) 75% (69.40m) 90% (136.94m)
Screenshot 2024-11-10 at 10 20 33 AM Screenshot 2024-11-10 at 10 21 13 AM Screenshot 2024-11-10 at 10 21 45 AM

@shankari
Copy link
Contributor Author

For the record, here's are the same metrics for the PSU phone

Trajectory boxplot of distance without outliers
Screenshot 2024-11-10 at 11 46 09 AM image

To summarize, working from a larger dataset of iPhones, we see that:

  • out of 21 iPhones in our sample, one has stats similar to what PSU is seeing (box upto ~ 150 meters, whisker upto 300m)
  • the trajectories of the "bad phone" in our sample also visually show gaps, but do not appear to show the "bunched" effect of the PSU phone. On the PSU phone, there is typically a burst of fine-grained data, and then a gap until the next point. The phone in our sample appears to have evenly spaced points

We can see this in the time boxplots - the median on the PSU phone is low, pulled down by the "bunches of points", while the median on the sample phone is high, representing a constant stream of widely spaced points.

PSU phone sample phone on the 75% trip, which shows widely spaced points
image image
Screenshot 2024-11-10 at 11 46 09 AM Screenshot 2024-11-10 at 10 21 13 AM

@shankari
Copy link
Contributor Author

Summary of the problem:

  • The "bad phone" problem is real
  • The "bad phone" problem is rare (incidence: 1/21 phones)
  • The "bad phone" problem does not appear to be tied to the iOS version
  • The "bad phone" problem manifests differently on different bad phones, so it is not clear if it is even the same problem.

Given this, I suggest the following next steps:

  • I add an option to turn off the distance filter completely, just in case it is the distance filter implementation in iOS that is messing us up
  • We try to poke around a bit more with the "bad phone" from the dataset above, which fortunately for us, appears to be one of our test phones. This may include communicating with Apple if it turns out to be an OS issue.
  • We consider sending over a known good phone to PSU so we can verify that the issue is with the phone and not the GPS signals in Portland

@Abby-Wheelis
Copy link
Member

We consider sending over a known good phone to PSU so we can verify that the issue is with the phone and not the GPS signals in Portland

For a moment we were considering sending my iPhoneSE (2nd gen) so I moved to a new opcode to verify tracking, thinking the fact I hadn't seen trips in a while was due to the pipeline being stuck, but when I got a notification yesterday that "trip tracking may not work".

IMG_9148

I'll try uninstalling and reinstalling the app to see if that gets tracking working - it's worth noting that I tracked a hike with Strava this weekend and had no issues, though I have no idea how OpenPATH tracking compares.

@Abby-Wheelis
Copy link
Member

I'll try uninstalling and reinstalling the app to see if that gets tracking working

For the first time in a while I have a trip record, but it is only the last 1/2 mile of my 3 mile commute home. Happy to provide logs/dump/screenshots on internal repo.

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

3 participants