Geofence exit is not triggered even when we move far way

[shankari]

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

1. We detect a trip end at

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

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

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

   

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

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

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

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

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

[shankari]

log file showing lack of geofence exit.
loggerDB.nogeofence_exit.withdate.log.zip

[shankari]

So it turns out that after that, I went to Berkeley and came back on Friday night. And the geofence exit was triggered right around City Hall. This makes it pretty clear that the geofence was still active, and apparently working sometimes, but not when I first exited it.

• Leaving Berkeley (2016-02-26 17:41:27)

  

• Exiting geofence (2016-02-26 19:43:44)

  

[shankari]

I see a second state check in the logs

We were inside the geofence on the 24th

4116,1456369216.22,2016-02-24 18:53:16.221400-08:00,started monitoring for region STATIONARY_GEOFENCE_LOCATION
4117,1456369216.79,2016-02-24 18:53:16.787890-08:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
4118,1456369216.81,2016-02-24 18:53:16.809020-08:00,Received INSIDE geofence state when currState = STATE_ONGOING_TRIP
4119,1456369216.83,2016-02-24 18:53:16.826770-08:00,Received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP
4120,1456369217.11,2016-02-24 18:53:17.113320-08:00,stopped fine location tracking
4121,1456369217.17,2016-02-24 18:53:17.173530-08:00,Received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP
4122,1456369217.53,2016-02-24 18:53:17.532440-08:00,Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START
4123,1456369217.55,2016-02-24 18:53:17.549100-08:00,Received notification T_TRIP_ENDED while processing silent push notification

Then, we print the results of a second check - dunno who issued the check, hope it wasn't a stuck thread from earlier.

5329,1456545038.46,2016-02-26 19:43:38.463860-08:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
5330,1456545038.51,2016-02-26 19:43:38.505050-08:00,Received INSIDE geofence state when currState = STATE_WAITING_FOR_TRIP_START
5331,1456545038.55,2016-02-26 19:43:38.545740-08:00,Received transition T_NOP in state STATE_WAITING_FOR_TRIP_START
5332,1456545038.63,2016-02-26 19:43:38.633660-08:00,Received notification T_NOP while processing silent push notification

And then we finally receive the real geofence exit.

5334,1456545044.3,2016-02-26 19:43:44.295710-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START
5335,1456545044.35,2016-02-26 19:43:44.345330-08:00,started fine location tracking
5336,1456545044.43,2016-02-26 19:43:44.431810-08:00,Received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START
5337,1456545044.53,2016-02-26 19:43:44.525320-08:00,Moved from STATE_WAITING_FOR_TRIP_START to STATE_ONGOING_TRIP
5338,1456545044.57,2016-02-26 19:43:44.573000-08:00,Received notification T_TRIP_STARTED while processing silent push notification

[shankari]

Full logs are here:
loggerDB.nogeofence_exit.withdate.log.zip