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.

Sign up for GitHub

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

Jump to bottom

Trips missing for several days #592

Closed
shankari opened this issue Dec 8, 2020 · 14 comments
Closed

Trips missing for several days #592

shankari opened this issue Dec 8, 2020 · 14 comments
Labels
app-android ceo-ebike

Comments

@shankari
Copy link
Contributor

shankari commented Dec 8, 2020

One of the COBike users was missing trips for around a week. After contacting her:

  • the token was correct
  • location services was turned on
  • the app had "always" permission
  • the app was in waiting_for_trip_start state

have asked for logs. Is this another instance of
e-mission/e-mission-data-collection#155
@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020

So the trips stopped recording around 30th Nov

159841,1606780909.641,2020-11-30T16:01:49.641000-08:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.exited_geofence) completed, waiting for async operations to complete"
162323,1606781995.039,2020-11-30T16:19:55.039000-08:00,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) called"
162326,1606781995.0670002,2020-11-30T16:19:55.067000-08:00,"TripDiaryStateMachineService : handleAction(local.state.ongoing_trip, local.transition.stopped_moving) completed, waiting for async operations to complete"
162442,1606783045.282,2020-11-30T16:37:25.282000-08:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"

The next action was today, after we called them

163053,1607454458.4989998,2020-12-08T11:07:38.499000-08:00,"TripDiaryStateMachineService : handleAction(local.state.waiting_for_trip_start, local.transition.initialize) called"

Looks like that initialize might have been the cause?

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020

That initialize was caused by a reboot

162424,1606783026.9870002,2020-11-30T16:37:06.987000-08:00,BootReceiver : BootReceiver.onReceive called
162425,1606783027.018,2020-11-30T16:37:07.018000-08:00,BuiltinUserCache : Added value for key statemachine/transition at time 1.60678302701E9
162428,1606783045.15,2020-11-30T16:37:25.150000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@4ec3bf2, Intent { act=local.transition.initialize flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

We then got a valid location

162448,1606783045.41,2020-11-30T16:37:25.410000-08:00,"CreateGeofenceAction : Last location would have been Location[fused LAT1,LON1 hAcc=12]}] if we hadn't reset it"

And then we successfully created the geofence

162451,1606783045.415,2020-11-30T16:37:25.415000-08:00,"CreateGeofenceAction : creating geofence at location Location[fused LAT1,LON1 hAcc=12]}]"
162454,1606783045.4870002,2020-11-30T16:37:25.487000-08:00,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start

And the permissions were all correct after that

162461,1606783045.525,2020-11-30T16:37:25.525000-08:00,LocationHandler : default request is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=3600000ms fastest=600000ms]
162462,1606783045.5270002,2020-11-30T16:37:25.527000-08:00,"LocationHandler : after applying config, value is Request[PRIORITY_BALANCED_POWER_ACCURACY requested=30000ms fastest=5000ms]"
162463,1606783045.53,2020-11-30T16:37:25.530000-08:00,SensorControlBackgroundChecker : Checking location settings and permissions for request Request[PRIORITY_BALANCED_POWER_ACCURACY requested=30000ms fastest=5000ms]
162464,1606783045.532,2020-11-30T16:37:25.532000-08:00,SensorControlBackgroundChecker : checkSelfPermission returned 0
162465,1606783045.534,2020-11-30T16:37:25.534000-08:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
162466,1606783045.536,2020-11-30T16:37:25.536000-08:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
162467,1606783045.539,2020-11-30T16:37:25.539000-08:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@c570d4c
162468,1606783045.5410001,2020-11-30T16:37:25.541000-08:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
162474,1606783045.6020002,2020-11-30T16:37:25.602000-08:00,"SensorControlBackgroundChecker : in restartFSMIfStartState, currState = local.state.waiting_for_trip_start"

Stayed fine even after that

162485,1606786021.135,2020-11-30T17:27:01.135000-08:00,"SensorControlBackgroundChecker : checkLocationPermissions returned true, checking background permission"
162486,1606786021.137,2020-11-30T17:27:01.137000-08:00,"SensorControlBackgroundChecker : checkBackgroundLocPermissions returned true, checking location settings"
162487,1606786021.157,2020-11-30T17:27:01.157000-08:00,SensorControlBackgroundChecker : Got back result com.google.android.gms.tasks.zzu@33a41f9
162488,1606786021.1620002,2020-11-30T17:27:01.162000-08:00,"SensorControlBackgroundChecker : checkMotionActivityPermissions returned false, but that's not a tracking error"
162489,1606786021.1720002,2020-11-30T17:27:01.172000-08:00,TripDiaryStateMachineRcvr : Comparing installed version 11 with new version 11

And then we have a bunch of valid periodic calls

162534,1606789378.925,2020-11-30T18:22:58.925000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
162548,1606789379.0029998,2020-11-30T18:22:59.003000-08:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
162550,1606789379.024,2020-11-30T18:22:59.024000-08:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
162590,1606792922.856,2020-11-30T19:22:02.856000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
162604,1606792922.926,2020-11-30T19:22:02.926000-08:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
162605,1606792922.9529998,2020-11-30T19:22:02.953000-08:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
162646,1606796522.885,2020-11-30T20:22:02.885000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
162660,1606796523.042,2020-11-30T20:22:03.042000-08:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
162661,1606796523.045,2020-11-30T20:22:03.045000-08:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"

This continues until

162926,1606829161.02,2020-12-01T05:26:01.020000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
162940,1606829161.1120002,2020-12-01T05:26:01.112000-08:00,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY
162949,1606829161.169,2020-12-01T05:26:01.169000-08:00,"SensorControlBackgroundChecker : All settings are valid, checking current state"
162977,1606829162.582,2020-12-01T05:26:02.582000-08:00,"ServerSyncAdapter : Finished sync, sending local broadcast"

Then we get these messages

162979,1606829438.44,2020-12-01T05:30:38.440000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
162980,1606829438.47,2020-12-01T05:30:38.470000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

And then there are no logs until

162981,1607395964.485,2020-12-07T18:52:44.485000-08:00,BootReceiver : BootReceiver.onReceive called
162982,1607395964.506,2020-12-07T18:52:44.506000-08:00,BuiltinUserCache : Added value for key statemachine/transition at time 1.607395964503E9

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020 •
edited
Loading

It is really surprising that we didn't have any logs between 01 and 07. If there were location issues, either due to permissions or location services, we should have still got periodic syncs.

The onDestroy calls for the foreground service

162979,1606829438.44,2020-12-01T05:30:38.440000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
162980,1606829438.47,2020-12-01T05:30:38.470000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

seem to indicate some kind of force kill or uninstallation.

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020 •
edited
Loading

We have seen prior issues with the onDestroy (#580 (comment))

It was related to the chrome update, which killed the foreground service. The lack of foreground service means that we only get very rare periodic location updates (e.g. every 5-6 hours) iff tracking was turned on.

But we did continue to get the periodic syncs. And we actually hooked into that to restart the service automatically as required. So the lack of periodic syncs indicates that there must have been some other problem.

Logs from the other bug.

83934,1600451172.4420002,2020-09-18T11:46:12.442000-06:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
83973,1600453303.524,2020-09-18T12:21:43.524000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84024,1600457373.17,2020-09-18T13:29:33.170000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84075,1600460774.1820002,2020-09-18T14:26:14.182000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
84126,1600464426.4970002,2020-09-18T15:27:06.497000-06:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020

Others have reported issues on starting foreground services from the background.
https://stackoverflow.com/questions/52850158/cant-start-foreground-service-from-background-in-android-p

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020 •
edited
Loading

The users is on Android 9. Maybe in Android P, the background sync invocations also don't happen if the app doesn't have a foreground service? Not quite sure how to fix this though. Maybe we do need to send push notifications after all?

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020 •
edited
Loading

This is the boot receiver that failed.

162981,1607395964.485,2020-12-07T18:52:44.485000-08:00,BootReceiver : BootReceiver.onReceive called

We then got a periodic sync several hours later, which finally did what it was supposed to do.

162988,1607454458.184,2020-12-08T11:07:38.184000-08:00,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.607454458163E9
162991,1607454458.221,2020-12-08T11:07:38.221000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
162992,1607454458.228,2020-12-08T11:07:38.228000-08:00,"TripDiaryStateMachineForegroundService : In checkForegroundNotification, found 1 active notifications"
162993,1607454458.231,2020-12-08T11:07:38.231000-08:00,TripDiaryStateMachineForegroundService : Did not find foreground notification with ID 6646464 in list [0]
162998,1607454458.2529998,2020-12-08T11:07:38.253000-08:00,"NotificationHelper : Generating notify with id 6646465 and message Primer plano servicio asesinar, Perfil -> Registro de correo electrónico con depurar"

That message is foreground_killed_email_log, which is generated from

https://github.com/e-mission/e-mission-data-collection/blob/9fbb7be13b33d34452800bd87f893ce3a82c26e5/src/android/location/TripDiaryStateMachineForegroundService.java#L164

The app was still in waiting for trip start

163005,1607454458.313,2020-12-08T11:07:38.313000-08:00,"TripDiaryStateMachineForegroundService : onStartCommand called on oreo+, with msg En estado local.state.waiting_for_trip_start starting foreground service"

We apparently generated an initalize (unsure why)

163015,1607454458.3760002,2020-12-08T11:07:38.376000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@87b43e4, Intent { act=local.transition.initialize flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

The app was upgraded in the interim

163018,1607454458.401,2020-12-08T11:07:38.401000-08:00,TripDiaryStateMachineRcvr : Comparing installed version 11 with new version 12
163019,1607454458.4060001,2020-12-08T11:07:38.406000-08:00,"TripDiaryStateMachineRcvr : Setup not complete, sending initialize"

which caused us to send and receive another initialize

163063,1607454458.5879998,2020-12-08T11:07:38.588000-08:00,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@87b43e4, Intent { act=local.transition.initialize flg=0x10 pkg=gov.colorado.energyoffice.emission cmp=gov.colorado.energyoffice.emission/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

And then after all the async operations complete, the foreground service is destroyed again!

163153,1607454560.086,2020-12-08T11:09:20.086000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
163154,1607454560.101,2020-12-08T11:09:20.101000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020

Let's look at prior instances of the foreground service being destroyed.

55203,1605499828.0979998,2020-11-15T20:10:28.098000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
55204,1605499828.1039999,2020-11-15T20:10:28.104000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
144948,1606491214.8839998,2020-11-27T07:33:34.884000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
144949,1606491214.917,2020-11-27T07:33:34.917000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
162979,1606829438.44,2020-12-01T05:30:38.440000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
162980,1606829438.47,2020-12-01T05:30:38.470000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
163153,1607454560.086,2020-12-08T11:09:20.086000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
163154,1607454560.101,2020-12-08T11:09:20.101000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
169181,1607456878.596,2020-12-08T11:47:58.596000-08:00,TripDiaryStateMachineForegroundService : onDestroy called for foreground service
169182,1607456878.5979998,2020-12-08T11:47:58.598000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020 •
edited
Loading

The user reported that they received a push notification at 11:08 on 2020-12-08. So the notifications were clearly on at the time, and the launch at 11:09:20 is probably related to that.

loggerDB.the_one_periodic_sync.gz

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020

In prior instances, the periodic sync workaround has worked. On the same phone.

55204,1605499828.1039999,2020-11-15T20:10:28.104000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
55208,1605501019.6260002,2020-11-15T20:30:19.626000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
...
144949,1606491214.917,2020-11-27T07:33:34.917000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
144953,1606498128.8760002,2020-11-27T09:28:48.876000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY

Until it didn't

162980,1606829438.47,2020-12-01T05:30:38.470000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
162991,1607454458.221,2020-12-08T11:07:38.221000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY

And then it did again

163154,1607454560.101,2020-12-08T11:09:20.101000-08:00,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
168229,1607456642.986,2020-12-08T11:44:02.986000-08:00,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020 •
edited
Loading

So this doesn't appear to be an android version issue because the restarts have happened both before and after the failed restart. So why didn't it restart only in the middle?

@shankari
Copy link
Contributor Author

shankari commented Dec 9, 2020

Will see if I can get developer logs from the user, or determine if they did anything special during that period.

@shankari
Copy link
Contributor Author

double checked on the server, and we did not receive any get messages in the interim

2020-12-01T05:32:09.987265+00:00
2020-12-01T07:00:02.749911+00:00
2020-12-01T08:58:12.930086+00:00
2020-12-01T12:30:22.780406+00:00
2020-12-01T13:26:02.125731+00:00
....
2020-12-08T19:07:39.595823+00:00
2020-12-08T19:44:04.438515+00:00
2020-12-08T20:03:03.082433+00:00
2020-12-08T21:08:02.200814+00:00
2020-12-08T22:08:14.729044+00:00

and we did start getting trips now.

Seems pretty likely that the user had uninstalled the app or turned something off, since everything was working before and after.

@shankari
Copy link
Contributor Author

see consistent trips even after a week. The person had probably uninstalled the app and reinstalled.
Closing this issue now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
app-android ceo-ebike
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@shankari