Silent push is not reliably received on iOS

[shankari]

The original idea behind using the silent push was to get a more reliable delivery mechanism than the background fetch, which is known to be flaky. However, during the first active test on Wednesday, we found in practice that remote pushes were also sometimes missing.

Consider the list of transitions for the phone which was using the geofence.

Until the first trip outside, we got pushes reliably:

[{u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T00:13:21.843242-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T01:14:49.064150-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T02:08:56.893655-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T03:14:49.806864-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T04:13:39.781748-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T05:29:36.176499-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T06:13:51.828550-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T07:09:08.884717-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T08:06:30.322389-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T09:08:41.975411-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T10:07:48.680031-08:00'}},

After returning from the first trip at 10:35, I expected to get a remote push at around 11. But no remote push was delivered until 11:40, at which time I issued another call manually, which caused the geofence to be recreated.

 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T11:43:40.942893-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T11:43:40.942893-08:00'}},

Again, there was no remote push at noon, when we were in drama class. The next remote push was only delivered after we returned home and I generated a manual push at 1:11pm.

{u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T13:11:07.990080-08:00'}},
 {u'data': {u'transition': 7},

After that, we receive consistent pushes until midnight with the 19:00 (7pm) and 22:00 (10pm) updates skipped.

{u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T14:20:00.524897-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T14:20:00.524897-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T15:00:04.690188-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T15:00:04.690188-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T16:00:06.035792-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T16:00:06.035792-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T17:00:04.928013-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T18:00:04.441931-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T18:00:04.441931-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T20:12:24.196366-08:00'}},
 {u'data': {u'transition': 7},
  u'metadata': {u'write_fmt_time': u'2015-11-25T21:14:52.841128-08:00'}}]

[shankari]

This is not a correctness issue, because the silent push will be received eventually. However, it is a performance issue, because our tests have shown that the power drain with a geofence is close to zero, while the power drain during monitoring, even with a distance filter, is significant.

Let us try switching to using visits instead. I've been displaying the results of the visit as notifications on the phone, and they seem to be fairly reliable. And using visits will ensure that we don't have to deal with setting up remote push, which is not as much of a pain as you might imagine, but is still a pain.

[shankari]

One fairly big question is, what do we do when the visit message is triggered? Do we just trust in the wisdom of iOS and say that the trip has ended, or do we do our own checks? It seems like it would be good to at least have the option of doing our own checks.

[shankari]

Hm. Looking back at the record of changes in the past, we see an issue with geofences. It looks like geofences are not created properly when we are in the background. Looking at the logs reported at the time:

Feb  9 16:02:35 location-test-iPhone2 CFC_Tracker[481] <Warning>: maxDistance = 33.924685 (< 100), returning YES
Feb  9 16:02:35 location-test-iPhone2 CFC_Tracker[481] <Warning>: Generating local notification with message Received transition TRANSITION_STOPPED_MOVING in state STATE_ONGOING_TRIP
Feb  9 16:02:36 location-test-iPhone2 CFC_Tracker[481] <Error>: CoreLocation: Sending an un-cached message without first clearing the previously cached value
Feb  9 16:02:36 location-test-iPhone2 CFC_Tracker[481] <Warning>: At method CREATION
Feb  9 16:02:36 location-test-iPhone2 CFC_Tracker[481] <Warning>: Found geofence with id STATIONARY_GEOFENCE_LOCATION, coordinates -122.083694 37.403827
Feb  9 16:02:36 location-test-iPhone2 CFC_Tracker[481] <Warning>: BEFORE creating region
Feb  9 16:02:36 location-test-iPhone2 CFC_Tracker[481] <Warning>: Found geofence with id STATIONARY_GEOFENCE_LOCATION, coordinates -122.083694 37.403827
Feb  9 16:02:36 location-test-iPhone2 CFC_Tracker[481] <Warning>: AFTER creating region
Feb  9 16:25:53 location-test-iPhone2 CFC_Tracker[481] <Warning>: Found geofence with id STATIONARY_GEOFENCE_LOCATION, coordinates -122.086465 37.391074
Feb  9 16:25:53 location-test-iPhone2 CFC_Tracker[481] <Warning>: started monitoring for region STATIONARY_GEOFENCE_LOCATION
Feb  9 16:25:53 location-test-iPhone2 CFC_Tracker[481] <Warning>: Generating local notification with message Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START

Note the ~ 25 minute gap between the call to create the geofence and the time that the monitoring started. I believe that I brought the app to the foreground around 4:25. Based on this, I am not sure whether the geofence would have ever triggered.

    [manager startMonitoringForRegion:geofenceRegion];
    NSLog(@"AFTER creating region");
    [self printGeofences:manager];

An advantage of using the push notification code is that the method does not exit, and the app get killed, until the completionMethod is called or 30 seconds have passed. This means that we are able to wait until the trip has completely ended before calling the completionMethod, which ensures that the geofence is set up correctly.

On the other hand, the evidence above is that the geofence delegate is not invoked unless it is in the main thread.

You must call this method once for each region you want to monitor. If an existing region with the same identifier is already being monitored by the app, the old region is replaced by the new one. The regions you add using this method are shared by all location manager objects in your app and stored in the monitoredRegions property.
Region events are delivered to the locationManager:didEnterRegion: and locationManager:didExitRegion: methods of your delegate. If there is an error, the location manager calls the locationManager:monitoringDidFailForRegion:withError: method of your delegate instead.
And
The methods of your delegate object are called from the thread in which you started the corresponding location services. That thread must itself have an active run loop, like the one found in your application’s main thread.

So does the delay in delivering the message to the delegate imply that there is also a delay in the creating the geofence, or is it just in the message delivery? Need to test. And if it is a delay in creating the geofence, then we need to use something like NSCondition to ensure that we don't return from the method until we know what has happened to the geofence.