[bug] Failure in recreating the geofence after reboot causes the app to be stuck in `waiting_for_trip_start` forever #678

shankari · 2021-10-09T15:27:26Z

This appears to be similar to #677 but happens much more infrequently.

On the order of one missing day over multiple months.

Reported by participants from Malawi and Denver.
Not sure if the underlying issue is the same for both of them.

The Malawi user, at least, had a pre-android 8.0 phone, so the foreground service is not necessary.

165243,1630744520.738,2021-09-04T10:35:20.738000+02:00,"TripDiaryStateMachineForegroundService : Pre-Oreo, no foreground service, no need to check for notification"

The Denver user has android 11, which should have the most restrictions ever.

The text was updated successfully, but these errors were encountered:

shankari · 2021-10-09T15:47:04Z

Starting with Malawi...; the user reports that they only had the outgoing trip recorded on 4th Sept; the return trip was missing.

Here's what we see for that user:

Trip started at 8:22

163601,1630736520.8620002,2021-09-04T08:22:00.862000+02:00,GeofenceExitIntentService : onCreate called

Trip ended at 8:32 and new geofence was created

164793,1630737136.647,2021-09-04T08:32:16.647000+02:00,"CreateGeofenceAction : Last location would have been Location[fused -1****,3**** ]}] if we hadn't reset it"
164794,1630737136.676,2021-09-04T08:32:16.676000+02:00,CreateGeofenceAction : isValidLocation = true. Yay!
164798,1630737136.756,2021-09-04T08:32:16.756000+02:00,"CreateGeofenceAction : creating geofence at location -1****, 3****"

Then we tried to create a geofence again 10 mins later. At this point, the current location was null. We tried to read the location so we could create the geofence...

165209,1630741467.31,2021-09-04T09:44:27.310000+02:00,CreateGeofenceAction : Last location would have been null if we hadn't reset it
165210,1630741467.312,2021-09-04T09:44:27.312000+02:00,"CreateGeofenceAction : mLastLocationTime = null, launching callback to read it and thencreate the geofence"
165211,1630741467.325,2021-09-04T09:44:27.325000+02:00,"CreateGeofenceAction : Successfully started tracking location, about to start waiting for location update"

We never did get said location, so we skipped creating the geofence.

shankari · 2021-10-09T15:48:21Z

So what happened between 8:32, when we successfully created the geofence and 9:44 when we tried to create it again, and failed?

Here's where we successfully created the geofence; we are now waiting for the trip start.

164799,1630737136.802,2021-09-04T08:32:16.802000+02:00,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start

The app was launched a few minutes later and the user accessed the label and
diary screens.

164816,1630737319.4120002,2021-09-04T08:35:19.412000+02:00,UnifiedLogger : finished init of android native code
...
164826,1630737324.0479999,2021-09-04T08:35:24.048000+02:00,js : ionicPlatform.ready() called 0 times!
...
164873,1630737324.8539999,2021-09-04T08:35:24.854000+02:00,js : Setting up the scrolling
...
164911,1630737331.8979998,2021-09-04T08:35:31.898000+02:00,js : Received batch of size 30
...
165075,1630737339.419,2021-09-04T08:35:39.419000+02:00,js : finished linking trips for list of size 1

Then, an hour later, we had a periodic call

165117,1630740556.2089999,2021-09-04T09:29:16.209000+02:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
...
165130,1630740556.294,2021-09-04T09:29:16.294000+02:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
...
165179,1630740568.444,2021-09-04T09:29:28.444000+02:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

Then, we had another of those quick reboots

165188,1630741070.881,2021-09-04T09:37:50.881000+02:00,"js : local and native values match, already synced"
165189,1630741427.3920002,2021-09-04T09:43:47.392000+02:00,BootReceiver : BootReceiver.onReceive called

but we weren't able to access the location, so we weren't able to create a geofence. All settings were valid, so this is probably due to poor GPS sightlines, or being too close to startup or ???

165213,1630741467.395,2021-09-04T09:44:27.395000+02:00,GeofenceLocationIntentService : onCreate called

165226,1630741470.5670002,2021-09-04T09:44:30.567000+02:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"

165235,1630741470.7470002,2021-09-04T09:44:30.747000+02:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"

The next periodic call was in around an hour. And we were in the waiting_for_trip_start state.

165258,1630744522.4789999,2021-09-04T10:35:22.479000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

Whoa! That seems like a real bug. It looks like we don't reset to the start state if we are in waiting_for_trip_start but not able to create a geofence.

This continues for the rest of the day.

165317,1630747967.3779998,2021-09-04T11:32:47.378000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
165372,1630751855.8920002,2021-09-04T12:37:35.892000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
165428,1630755157.2410002,2021-09-04T13:32:37.241000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
165487,1630758866.025,2021-09-04T14:34:26.025000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
165542,1630763141.65,2021-09-04T15:45:41.650000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

shankari · 2021-10-09T17:23:16Z

Bingo The second issue also seems to be the same.

167829,1633202340.746,2021-10-02T13:19:00.746000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"
167843,1633202340.8979998,2021-10-02T13:19:00.898000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

There's some additional complexity in this one, but I think it comes down to the same error.

shankari · 2021-10-10T02:41:01Z

Additional complexity:

We started off with tracking stopped, then the app was launched, and tracking was turned on.

154237,1633068900.101,2021-10-01T00:15:00.101000-06:00,js : ionicPlatform is ready

154284,1633068900.342,2021-10-01T00:15:00.342000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.tracking_stopped"

154567,1633068913.0670002,2021-10-01T00:15:13.067000-06:00,TransitionNotificationReceiver : Received platform-specification notification local.transition.start_tracking

154578,1633068913.106,2021-10-01T00:15:13.106000-06:00,TripDiaryStateMachineService : TripDiaryStateMachineReceiver handleTrackingStopped(local.transition.start_tracking) called

154579,1633068913.1079998,2021-10-01T00:15:13.108000-06:00,TripDiaryStateMachineService : newState after handling action is local.state.start

154601,1633068913.16,2021-10-01T00:15:13.160000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.start"

However, there were persistent issues with location availability so we were not able to create the geofence.

154616,1633068913.201,2021-10-01T00:15:13.201000-06:00,"TripDiaryStateMachineService : handleAction(local.state.start, local.transition.initialize) called"

154645,1633068913.264,2021-10-01T00:15:13.264000-06:00,CreateGeofenceAction : testLoc.getTime() = Thu Sep 30 23:41:37 MDT 2021 testLoc.oldness -2015302 > 18000000 isValidLocation = false
154646,1633068913.266,2021-10-01T00:15:13.266000-06:00,"CreateGeofenceAction : mLastLocationTime = null, launching callback to read it and thencreate the geofence"
154655,1633068913.2810001,2021-10-01T00:15:13.281000-06:00,CreateGeofenceAction : testLoc.getTime() = Thu Sep 30 23:41:37 MDT 2021 testLoc.oldness -2015320 > 18000000 isValidLocation = false
154664,1633068913.311,2021-10-01T00:15:13.311000-06:00,GeofenceLocationIntentService : availability = false

154674,1633068913.326,2021-10-01T00:15:13.326000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"
154676,1633068913.332,2021-10-01T00:15:13.332000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"

...

156572,1633068917.08,2021-10-01T00:15:17.080000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"
156628,1633068917.19,2021-10-01T00:15:17.190000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.start"

However, right after that we got a bunch of locations - I guess the location
service took some time to initialize and by that time, we had a ton of
queries. We then went to waiting_for_trip_start

156608,1633068917.1479998,2021-10-01T00:15:17.148000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156609,1633068917.154,2021-10-01T00:15:17.154000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156610,1633068917.1560001,2021-10-01T00:15:17.156000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156611,1633068917.158,2021-10-01T00:15:17.158000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156612,1633068917.159,2021-10-01T00:15:17.159000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156613,1633068917.161,2021-10-01T00:15:17.161000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156614,1633068917.1620002,2021-10-01T00:15:17.162000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156615,1633068917.165,2021-10-01T00:15:17.165000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156616,1633068917.1660001,2021-10-01T00:15:17.166000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }
156617,1633068917.169,2021-10-01T00:15:17.169000-06:00,CreateGeofenceAction : recieved broadcast intent Intent { act=GEOFENCE_LOCATION_RESULT (has extras) }

156629,1633068917.191,2021-10-01T00:15:17.191000-06:00,CreateGeofenceAction : isValidLocation = true. Yay!
156717,1633068917.3979998,2021-10-01T00:15:17.398000-06:00,"CreateGeofenceAction : creating geofence at location 3*********, -1**********"
156718,1633068917.4020002,2021-10-01T00:15:17.402000-06:00,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start

156740,1633068917.456,2021-10-01T00:15:17.456000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

After that, we stay in that state, quite correctly, until 1pm on the next day.
During the sync at around 1pm, everything was valid.

167757,1633200829.302,2021-10-02T12:53:49.302000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

Then, we rebooted!! Really and truly.

167778,1633200830.169,2021-10-02T12:53:50.169000-06:00,"ServerSyncAdapter : Finished sync, sending local broadcast"
167779,1633200830.18,2021-10-02T12:53:50.180000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.633200830177E9


167780,1633202284.851,2021-10-02T13:18:04.851000-06:00,BootReceiver : BootReceiver.onReceive called

In the subsequent sync, we again didn't get any location points, probably
because the location service was still initializing. And we are stuck in the
waiting_for_trip_start.

167798,1633202340.313,2021-10-02T13:19:00.313000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
167829,1633202340.746,2021-10-02T13:19:00.746000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"
167843,1633202340.8979998,2021-10-02T13:19:00.898000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

shankari · 2021-10-10T03:34:46Z

Another report: missing all trips between 14th and 17th.

Everything is fine until the 2021-09-14T17:....

167915,1631660601.1420002,2021-09-14T17:03:21.142000-06:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
167916,1631660601.144,2021-09-14T17:03:21.144000-06:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

Then we start a sync

167917,1631665983.893,2021-09-14T18:33:03.893000-06:00,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.631665983875E9
167918,1631665983.9120002,2021-09-14T18:33:03.912000-06:00,BuiltinUserCache : Added value for key background/battery at time 1.631665983899E9
167920,1631665983.93,2021-09-14T18:33:03.930000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY

which generates an initialize (unsure why, no reboot?)

167981,1631665984.6920002,2021-09-14T18:33:04.692000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"

Again, we can't create the geofence, and so all tracking is off until the next reboot re-initializes the FSM.

168005,1631665984.9889998,2021-09-14T18:33:04.989000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"

172892,1631925515.276,2021-09-17T18:38:35.276000-06:00,BootReceiver : BootReceiver.onReceive called
172909,1631925530.053,2021-09-17T18:38:50.053000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"

172920,1631925530.221,2021-09-17T18:38:50.221000-06:00,"CreateGeofenceAction : creating geofence at location 3*******, -1*******"

172989,1631926508.099,2021-09-17T18:55:08.099000-06:00,GeofenceExitIntentService : onCreate called

shankari · 2021-10-11T16:06:44Z

which generates an initialize (unsure why, no reboot?)

This is because the foreground service was killed just before that, and we reinitialize the FSM in that case.
https://github.com/e-mission/e-mission-data-collection/blob/58ae59add95097dbfdd1f1a9ef2bbcd8f6ec711b/src/android/location/TripDiaryStateMachineForegroundService.java#L191

We see this happening consistently for this user. Most of the time, the initialize succeeds; it failed in this one case.
Also, interestingly, a lot of times, the foreground service seems to be killed as part of a reboot. That's why we get multiple "initialize" transitions - one from the reboot and one from the foreground service kill.

6658,1629769664.81,2021-08-23T19:47:44.810000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
6682,1629769665.569,2021-08-23T19:47:45.569000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
6737,1629769694.734,2021-08-23T19:48:14.734000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
6796,1629769795.266,2021-08-23T19:49:55.266000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
6799,1629769795.321,2021-08-23T19:49:55.321000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"

20939,1629984042.631,2021-08-26T07:20:42.631000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
20962,1629984044.165,2021-08-26T07:20:44.165000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
21022,1629984062.069,2021-08-26T07:21:02.069000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
21060,1629984179.064,2021-08-26T07:22:59.064000-06:00,BootReceiver : BootReceiver.onReceive called
21077,1629984184.446,2021-08-26T07:23:04.446000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
21080,1629984184.4629998,2021-08-26T07:23:04.463000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"
21136,1629984187.154,2021-08-26T07:23:07.154000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
21152,1629984203.494,2021-08-26T07:23:23.494000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
21155,1629984203.519,2021-08-26T07:23:23.519000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"

78841,1630651377.889,2021-09-03T00:42:57.889000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
78858,1630651381.2429998,2021-09-03T00:43:01.243000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
78900,1630651535.6039999,2021-09-03T00:45:35.604000-06:00,BootReceiver : BootReceiver.onReceive called
78917,1630651545.86,2021-09-03T00:45:45.860000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
78920,1630651545.871,2021-09-03T00:45:45.871000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"
78949,1630651546.154,2021-09-03T00:45:46.154000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
78965,1630651560.816,2021-09-03T00:46:00.816000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
78968,1630651560.84,2021-09-03T00:46:00.840000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"

102138,1631020343.8339999,2021-09-07T07:12:23.834000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
102171,1631020344.508,2021-09-07T07:12:24.508000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
102175,1631020344.532,2021-09-07T07:12:24.532000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"

167927,1631665983.986,2021-09-14T18:33:03.986000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
167962,1631665984.357,2021-09-14T18:33:04.357000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
167981,1631665984.6920002,2021-09-14T18:33:04.692000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
167984,1631665984.7029998,2021-09-14T18:33:04.703000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"


168005,1631665984.9889998,2021-09-14T18:33:04.989000-06:00,"CreateGeofenceAction : Was not able to read new location, skipping geofence creation"

172830,1631925399.289,2021-09-17T18:36:39.289000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
172852,1631925399.994,2021-09-17T18:36:39.994000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
172892,1631925515.276,2021-09-17T18:38:35.276000-06:00,BootReceiver : BootReceiver.onReceive called
172909,1631925530.053,2021-09-17T18:38:50.053000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
172912,1631925530.066,2021-09-17T18:38:50.066000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"
172941,1631925530.481,2021-09-17T18:38:50.481000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
172957,1631925545.0310001,2021-09-17T18:39:05.031000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"
172960,1631925545.072,2021-09-17T18:39:05.072000-06:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) completed, waiting for async operations to complete"

shankari · 2021-10-11T16:19:51Z

Focusing only on the BootReceiver and the killed notification, they seem to be fairly correlated, but not perfect.

6658,1629769664.81,2021-08-23T19:47:44.810000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
6779,1629769789.4970002,2021-08-23T19:49:49.497000-06:00,BootReceiver : BootReceiver.onReceive called

20939,1629984042.631,2021-08-26T07:20:42.631000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
21060,1629984179.064,2021-08-26T07:22:59.064000-06:00,BootReceiver : BootReceiver.onReceive called

25299,1630007062.485,2021-08-26T13:44:22.485000-06:00,BootReceiver : BootReceiver.onReceive called

36919,1630161164.67,2021-08-28T08:32:44.670000-06:00,BootReceiver : BootReceiver.onReceive called

78841,1630651377.889,2021-09-03T00:42:57.889000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
78900,1630651535.6039999,2021-09-03T00:45:35.604000-06:00,BootReceiver : BootReceiver.onReceive called

102138,1631020343.8339999,2021-09-07T07:12:23.834000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"

167927,1631665983.986,2021-09-14T18:33:03.986000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
172830,1631925399.289,2021-09-17T18:36:39.289000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
172892,1631925515.276,2021-09-17T18:38:35.276000-06:00,BootReceiver : BootReceiver.onReceive called

Not sure why we should get a BootReceiver callback right after the killed notification. It seems like we should first get the BootReciever and then launch the code that checks for the notification.

shankari · 2021-10-11T22:37:01Z

Not sure why we should get a BootReceiver callback right after the killed notification. It seems like we should first get the BootReciever and then launch the code that checks for the notification.

Focusing on a couple of instances of this...

6658,1629769664.81,2021-08-23T19:47:44.810000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
6779,1629769789.4970002,2021-08-23T19:49:49.497000-06:00,BootReceiver : BootReceiver.onReceive called

First sync, killed notification detection

6651,1629769662.889,2021-08-23T19:47:42.889000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
6658,1629769664.81,2021-08-23T19:47:44.810000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
6678,1629769665.524,2021-08-23T19:47:45.524000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
6685,1629769665.728,2021-08-23T19:47:45.728000-06:00,ServerSyncAdapter : Starting sync with push
6718,1629769670.8339999,2021-08-23T19:47:50.834000-06:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

Second sync almost immediately afterwards!!

6723,1629769694.373,2021-08-23T19:48:14.373000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
6724,1629769694.415,2021-08-23T19:48:14.415000-06:00,"TripDiaryStateMachineForegroundService : In checkForegroundNotification, found 2 active notifications"
6741,1629769694.8170002,2021-08-23T19:48:14.817000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
6777,1629769701.691,2021-08-23T19:48:21.691000-06:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

And then the reboot:

6778,1629769701.7570002,2021-08-23T19:48:21.757000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629769701728E9
6779,1629769789.4970002,2021-08-23T19:49:49.497000-06:00,BootReceiver : BootReceiver.onReceive called

shankari · 2021-10-11T22:48:10Z

Similarly,

172823,1631925398.668,2021-09-17T18:36:38.668000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
172830,1631925399.289,2021-09-17T18:36:39.289000-06:00,"NotificationHelper : Generating notify with id 6646465 and message Foreground service killed, report at Profile -> Upload Log"
172854,1631925400.049,2021-09-17T18:36:40.049000-06:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

172857,1631925400.345,2021-09-17T18:36:40.345000-06:00,ServerSyncAdapter : Starting sync with push
172890,1631925425.147,2021-09-17T18:37:05.147000-06:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

172892,1631925515.276,2021-09-17T18:38:35.276000-06:00,BootReceiver : BootReceiver.onReceive called

shankari · 2021-10-11T22:50:03Z

Looks like most of the reboots were super fast (under 1 minute).

$ grep --before-context=1 BootReceiver /tmp/2021-09-21_Per_shankari_America_Denver.loggerDB.withdate.log
6778,1629769701.7570002,2021-08-23T19:48:21.757000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629769701728E9
6779,1629769789.4970002,2021-08-23T19:49:49.497000-06:00,BootReceiver : BootReceiver.onReceive called
--
21059,1629984068.1660001,2021-08-26T07:21:08.166000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629984068148E9
21060,1629984179.064,2021-08-26T07:22:59.064000-06:00,BootReceiver : BootReceiver.onReceive called
--
25298,1630005608.826,2021-08-26T13:20:08.826000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630005608824E9
25299,1630007062.485,2021-08-26T13:44:22.485000-06:00,BootReceiver : BootReceiver.onReceive called
--
36918,1630150720.655,2021-08-28T05:38:40.655000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630150720654E9
36919,1630161164.67,2021-08-28T08:32:44.670000-06:00,BootReceiver : BootReceiver.onReceive called
--
78899,1630651390.505,2021-09-03T00:43:10.505000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630651390479E9
78900,1630651535.6039999,2021-09-03T00:45:35.604000-06:00,BootReceiver : BootReceiver.onReceive called
--
172891,1631925425.2570002,2021-09-17T18:37:05.257000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.631925425206E9
172892,1631925515.276,2021-09-17T18:38:35.276000-06:00,BootReceiver : BootReceiver.onReceive called

shankari · 2021-10-11T22:58:14Z

I see this pattern of very short restarts for the Malawi user as well.

328,1628688186.27,2021-08-11T15:23:06.270000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628688186266E9
329,1628690567.592,2021-08-11T16:02:47.592000+02:00,BootReceiver : BootReceiver.onReceive called

More and more

--
6772,1628767542.5670002,2021-08-12T13:25:42.567000+02:00,ActivityRecognitionChangeIntentService : onDestroy called
6773,1628767891.9629998,2021-08-12T13:31:31.963000+02:00,BootReceiver : BootReceiver.onReceive called
--
8226,1628780608.7129998,2021-08-12T17:03:28.713000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628780608517E9
8227,1628780663.7529998,2021-08-12T17:04:23.753000+02:00,BootReceiver : BootReceiver.onReceive called
--
8707,1628791110.59,2021-08-12T19:58:30.590000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628791110588E9
8708,1628793059.69,2021-08-12T20:30:59.690000+02:00,BootReceiver : BootReceiver.onReceive called
--
8799,1628794752.394,2021-08-12T20:59:12.394000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628794752381E9
8800,1628797878.68,2021-08-12T21:51:18.680000+02:00,BootReceiver : BootReceiver.onReceive called
--
10246,1628867994.2979999,2021-08-13T17:19:54.298000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628867994294E9
10247,1628868357.815,2021-08-13T17:25:57.815000+02:00,BootReceiver : BootReceiver.onReceive called
--
14242,1628943278.052,2021-08-14T14:14:38.052000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628943277997E9
14243,1628943422.964,2021-08-14T14:17:02.964000+02:00,BootReceiver : BootReceiver.onReceive called
--
14285,1628943519.429,2021-08-14T14:18:39.429000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
14286,1628949614.9220002,2021-08-14T16:00:14.922000+02:00,BootReceiver : BootReceiver.onReceive called
--
14339,1628955134.699,2021-08-14T17:32:14.699000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628955134389E9
14340,1628955269.57,2021-08-14T17:34:29.570000+02:00,BootReceiver : BootReceiver.onReceive called
--
14652,1628973245.756,2021-08-14T22:34:05.756000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.628973245611E9
14653,1628973341.9629998,2021-08-14T22:35:41.963000+02:00,BootReceiver : BootReceiver.onReceive called
--
14919,1629013625.2729998,2021-08-15T09:47:05.273000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629013625125E9
14920,1629013816.208,2021-08-15T09:50:16.208000+02:00,BootReceiver : BootReceiver.onReceive called
--
17081,1629043062.381,2021-08-15T17:57:42.381000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629043062358E9
17082,1629043175.248,2021-08-15T17:59:35.248000+02:00,BootReceiver : BootReceiver.onReceive called
--
17601,1629103068.9929998,2021-08-16T10:37:48.993000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629103068378E9
17602,1629103238.855,2021-08-16T10:40:38.855000+02:00,BootReceiver : BootReceiver.onReceive called
--
43689,1629293356.274,2021-08-18T15:29:16.274000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629293356267E9
43690,1629295807.728,2021-08-18T16:10:07.728000+02:00,BootReceiver : BootReceiver.onReceive called
--
52229,1629533150.63,2021-08-21T10:05:50.630000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629533150553E9
52230,1629533242.495,2021-08-21T10:07:22.495000+02:00,BootReceiver : BootReceiver.onReceive called
--
90951,1629911946.2089999,2021-08-25T19:19:06.209000+02:00,js : User skipped deploy update
90952,1629912186.591,2021-08-25T19:23:06.591000+02:00,BootReceiver : BootReceiver.onReceive called
--
91081,1629916533.917,2021-08-25T20:35:33.917000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629916533913E9
91082,1629927087.76,2021-08-25T23:31:27.760000+02:00,BootReceiver : BootReceiver.onReceive called
--
91303,1629951953.356,2021-08-26T06:25:53.356000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.629951953339E9
91304,1629952039.484,2021-08-26T06:27:19.484000+02:00,BootReceiver : BootReceiver.onReceive called
--
102009,1629992006.732,2021-08-26T17:33:26.732000+02:00,"ConnectionSettings : in getConnectURL, returning https://stage.canbikeco.org"
102010,1629992007.2020001,2021-08-26T17:33:27.202000+02:00,BootReceiver : BootReceiver.onReceive called
--
103067,1630004571.522,2021-08-26T21:02:51.522000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630004571482E9
103068,1630004571.995,2021-08-26T21:02:51.995000+02:00,BootReceiver : BootReceiver.onReceive called
--
128863,1630326779.821,2021-08-30T14:32:59.821000+02:00,"ForegroundServiceComm : Destroying FSM service, unbinding foreground service"
128864,1630328493.681,2021-08-30T15:01:33.681000+02:00,BootReceiver : BootReceiver.onReceive called
--
133231,1630384435.552,2021-08-31T06:33:55.552000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630384435548E9
133232,1630391050.8760002,2021-08-31T08:24:10.876000+02:00,BootReceiver : BootReceiver.onReceive called
--
133330,1630391209.1220002,2021-08-31T08:26:49.122000+02:00,"ForegroundServiceComm : Destroying FSM service, unbinding foreground service"
133331,1630393296.272,2021-08-31T09:01:36.272000+02:00,BootReceiver : BootReceiver.onReceive called
--
135549,1630403675.904,2021-08-31T11:54:35.904000+02:00,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@84fb931 with status HTTP/1.1 200 OK
135550,1630403678.446,2021-08-31T11:54:38.446000+02:00,BootReceiver : BootReceiver.onReceive called
--
135612,1630403843.934,2021-08-31T11:57:23.934000+02:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
135613,1630404673.988,2021-08-31T12:11:13.988000+02:00,BootReceiver : BootReceiver.onReceive called
--
141668,1630421474.361,2021-08-31T16:51:14.361000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630421474355E9
141669,1630421500.504,2021-08-31T16:51:40.504000+02:00,BootReceiver : BootReceiver.onReceive called
--
143289,1630478370.599,2021-09-01T08:39:30.599000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630478370515E9
143290,1630478393.8779998,2021-09-01T08:39:53.878000+02:00,BootReceiver : BootReceiver.onReceive called
--
148263,1630507303.2910001,2021-09-01T16:41:43.291000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630507303287E9
148264,1630509424.801,2021-09-01T17:17:04.801000+02:00,BootReceiver : BootReceiver.onReceive called
--
148477,1630520271.65,2021-09-01T20:17:51.650000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630520271592E9
148478,1630520292.564,2021-09-01T20:18:12.564000+02:00,BootReceiver : BootReceiver.onReceive called
--
162567,1630665260.189,2021-09-03T12:34:20.189000+02:00,BuiltinUserCache : Added value for key stats/client_time at time 1.630665260178E9
162568,1630665443.904,2021-09-03T12:37:23.904000+02:00,BootReceiver : BootReceiver.onReceive called

165188,1630741070.881,2021-09-04T09:37:50.881000+02:00,"js : local and native values match, already synced"
165189,1630741427.3920002,2021-09-04T09:43:47.392000+02:00,BootReceiver : BootReceiver.onReceive called

shankari · 2021-10-11T23:07:46Z

More reboots for the same user.

438,1631399602.315,2021-09-11T16:33:22.315000-06:00,LocationChangeIntentService : onDestroy called
439,1631404949.7220001,2021-09-11T18:02:29.722000-06:00,BootReceiver : BootReceiver.onReceive called

More, more, more

722,1631410904.075,2021-09-11T19:41:44.075000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.63141090407E9
723,1631410964.949,2021-09-11T19:42:44.949000-06:00,BootReceiver : BootReceiver.onReceive called
--
83212,1631807935.883,2021-09-16T09:58:55.883000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.631807935876E9
83213,1631809956.606,2021-09-16T10:32:36.606000-06:00,BootReceiver : BootReceiver.onReceive called
--
101639,1631919041.639,2021-09-17T16:50:41.639000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.631919041635E9
101640,1631919850.611,2021-09-17T17:04:10.611000-06:00,BootReceiver : BootReceiver.onReceive called
--
152443,1632233916.978,2021-09-21T08:18:36.978000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.632233916959E9
152444,1632234001.947,2021-09-21T08:20:01.947000-06:00,BootReceiver : BootReceiver.onReceive called
--
172648,1632313013.449,2021-09-22T06:16:53.449000-06:00,BuiltinUserCache : received 7 items
172649,1632313014.194,2021-09-22T06:16:54.194000-06:00,BootReceiver : BootReceiver.onReceive called
--
175146,1632324868.2089999,2021-09-22T09:34:28.209000-06:00,"ConnectionSettings : in getConnectURL, returning https://stage.canbikeco.org"
175147,1632324869.1360002,2021-09-22T09:34:29.136000-06:00,BootReceiver : BootReceiver.onReceive called
--
199249,1632435879.139,2021-09-23T16:24:39.139000-06:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"
199250,1632436851.494,2021-09-23T16:40:51.494000-06:00,BootReceiver : BootReceiver.onReceive called
--
222937,1632531915.742,2021-09-24T19:05:15.742000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.632531915268E9
222938,1632533711.1079998,2021-09-24T19:35:11.108000-06:00,BootReceiver : BootReceiver.onReceive called
--
227887,1632586589.461,2021-09-25T10:16:29.461000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.632586589224E9
227888,1632586726.323,2021-09-25T10:18:46.323000-06:00,BootReceiver : BootReceiver.onReceive called
--
262079,1632841992.698,2021-09-28T09:13:12.698000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.632841992676E9
262080,1632842052.4129999,2021-09-28T09:14:12.413000-06:00,BootReceiver : BootReceiver.onReceive called
--
317979,1633103466.7129998,2021-10-01T09:51:06.713000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.633103466692E9
317980,1633103513.425,2021-10-01T09:51:53.425000-06:00,BootReceiver : BootReceiver.onReceive called
--
343602,1633209440.9789999,2021-10-02T15:17:20.979000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.633209440975E9
343603,1633209482.434,2021-10-02T15:18:02.434000-06:00,BootReceiver : BootReceiver.onReceive called
--
348230,1633276039.312,2021-10-03T09:47:19.312000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.633276039296E9
348231,1633276091.0170002,2021-10-03T09:48:11.017000-06:00,BootReceiver : BootReceiver.onReceive called
--
360745,1633363333.265,2021-10-04T10:02:13.265000-06:00,LocationChangeIntentService : onDestroy called
360746,1633363546.931,2021-10-04T10:05:46.931000-06:00,BootReceiver : BootReceiver.onReceive called
--
366928,1633390858.034,2021-10-04T17:40:58.034000-06:00,BuiltinUserCache : Reading entry = 0 with key config/sensor_config and write_ts 1.630095730843E9
366929,1633390860.428,2021-10-04T17:41:00.428000-06:00,BootReceiver : BootReceiver.onReceive called
--
410444,1633631590.214,2021-10-07T12:33:10.214000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.633631590146E9
410445,1633631657.393,2021-10-07T12:34:17.393000-06:00,BootReceiver : BootReceiver.onReceive called

412626,1633660013.2020001,2021-10-07T20:26:53.202000-06:00,BuiltinUserCache : Added value for key stats/client_time at time 1.633660013181E9
412627,1633660095.823,2021-10-07T20:28:15.823000-06:00,BootReceiver : BootReceiver.onReceive called

shankari · 2021-10-11T23:20:59Z

The trip segmentation algorithms do handle reboots, of course, but they assume that they are rare, and that we don’t know what the start point of the post-reboot trip is, so they don’t fill in the start of the trip. If they are this common and this short, I might need to handle them differently.

shankari changed the title ~~Occasional missing days of data collection~~ [bug] Failure in recreating the geofence after reboot causes the app to be stuck in waiting_for_trip_start forever Oct 10, 2021

This was referenced Oct 13, 2021

Intermittent tracking due to missing foreground service in Malawi on Huawei phones #677

Open

⬆️ Upgrade to latest everything 🎉 #680

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[bug] Failure in recreating the geofence after reboot causes the app to be stuck in `waiting_for_trip_start` forever #678

[bug] Failure in recreating the geofence after reboot causes the app to be stuck in `waiting_for_trip_start` forever #678

shankari commented Oct 9, 2021 •

edited

shankari commented Oct 9, 2021

shankari commented Oct 9, 2021

shankari commented Oct 9, 2021

shankari commented Oct 10, 2021

shankari commented Oct 10, 2021

shankari commented Oct 11, 2021 •

edited

shankari commented Oct 11, 2021 •

edited

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

[bug] Failure in recreating the geofence after reboot causes the app to be stuck in waiting_for_trip_start forever #678

[bug] Failure in recreating the geofence after reboot causes the app to be stuck in waiting_for_trip_start forever #678

Comments

shankari commented Oct 9, 2021 • edited

shankari commented Oct 9, 2021

shankari commented Oct 9, 2021

shankari commented Oct 9, 2021

shankari commented Oct 10, 2021

shankari commented Oct 10, 2021

shankari commented Oct 11, 2021 • edited

shankari commented Oct 11, 2021 • edited

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

shankari commented Oct 11, 2021

[bug] Failure in recreating the geofence after reboot causes the app to be stuck in `waiting_for_trip_start` forever #678

[bug] Failure in recreating the geofence after reboot causes the app to be stuck in `waiting_for_trip_start` forever #678

shankari commented Oct 9, 2021 •

edited

shankari commented Oct 11, 2021 •

edited

shankari commented Oct 11, 2021 •

edited