search

e-mission / e-mission-docs

Repository for docs and issues. If you need help, please file an issue here. Public conversations are better for open source projects than private email.
https://e-mission.readthedocs.io/en/latest
BSD 3-Clause "New" or "Revised" License
15 stars 34 forks source link

Consent deletion is not handled gracefully #228

Closed shankari closed 5 years ago

shankari commented 8 years ago

After investigating and fixing https://github.com/e-mission/cordova-jwt-auth/issues/8, we found that it had at least two occurrences in the real world. Furthermore, the users reported that:

  1. they never got notifications about the data collection being suspended due to no consent
  2. even after the fix was in, data collection was not resumed because:
    1. although the token is now valid, the consent is in the localStorage, although not in the native code, so we move on to the metrics
    2. the remote pushes have stopped because we don't register for them if we are not consented, so the consent document from the server is never retrieved

We just really need to make the consent thing a lot better.

shankari commented 8 years ago

It looks like we have a couple of potential choices if the localStorage shows consented but the native usercache does not:

  1. we can pop up the reconsent screen
  2. we can just mark the native as consented, since there is currently no way to unconsent, and the presence in the localStorage implies that the user did consent at one point.

I think that 1. has the potential to be confusing because going to the reconsent state after already going to the users' actual state may be confusing. This is particularly true if this takes a while. I was in profile, suddenly I go back to the consent. Then after going through that, I go back to metrics.

Also, would we need to think through what will happen in the very first case? In that case, there is no consent even in the localstorage, so this won't even be invoked.

Regardless, I am going to go with (2) since it is the least confusing, and will fall back to (1) if (2) fails.

shankari commented 8 years ago

The reason for 1 can be seen from this repro log, uploaded with consent. real_repro-upgrade-fix.log.gz

When the UI is launched, then all plugins are launched, as evidenced by this statement 

- (void)pluginInitialize
{
    // TODO: We should consider adding a create statement to the init, similar
    // to android - then it doesn't matter if the pre-populated database is not
    // copied over.
    NSLog(@"UnifiedLogger:pluginInitialize singleton -> initialize native DB");
    [[DBLogging database] log:@"finished init of iOS native code" atLevel:@"INFO"];
    [[DBLogging database] truncateObsolete];
}

But when the background sync is launched, it looks like the plugins are NOT launched.

First launch

0,1475866995.87,2016-10-07 12:56:15.865810-07:00,finished init of iOS native code
125,1475867106.03,2016-10-07 12:58:06.033280-07:00,Application went to the background

Next background sync

126,1475870408.65,2016-10-07 13:53:08.646500-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
132,1475870408.7,2016-10-07 13:53:08.698160-07:00,backgroundSync called
151,1475870408.82,2016-10-07 13:53:08.818070-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
157,1475870408.87,2016-10-07 13:53:08.867820-07:00,backgroundSync called
177,1475870408.99,2016-10-07 13:53:08.992890-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 21:00:08 +0000"
186,1475870409.04,2016-10-07 13:53:09.041810-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 21:00:08 +0000"

Next background sync

231,1475874004.5,2016-10-07 14:53:04.504950-07:00,backgroundSync called
251,1475874004.93,2016-10-07 14:53:04.931290-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:00:04 +0000"
267,1475874022.1,2016-10-07 14:53:22.095960-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
274,1475874022.21,2016-10-07 14:53:22.213480-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:00:04 +0000"
276,1475874022.23,2016-10-07 14:53:22.232890-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:00:04 +0000"
278,1475874022.27,2016-10-07 14:53:22.266390-07:00,backgroundSync called

Then, the application went to the background (not before this?) and again, it was launched without any plugins being initialized.

473,1475877603.1,2016-10-07 15:53:03.100710-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
480,1475877603.16,2016-10-07 15:53:03.162850-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:47:34 +0000"
482,1475877603.21,2016-10-07 15:53:03.212260-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:47:34 +0000"
484,1475877603.24,2016-10-07 15:53:03.240740-07:00,backgroundSync called
502,1475877605.58,2016-10-07 15:53:05.575370-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
509,1475877605.63,2016-10-07 15:53:05.626210-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:47:34 +0000"
511,1475877605.68,2016-10-07 15:53:05.683430-07:00,"Finished refreshing token in background, new expiry is 2016-10-07 22:47:34 +0000"
513,1475877605.71,2016-10-07 15:53:05.713850-07:00,backgroundSync called
561,1475877638.4,2016-10-07 15:53:38.403590-07:00,Application went to the background

And our notification that it is suspended is at, which is never launched from the background.

- (void)pluginInitialize
{
    // TODO: We should consider adding a create statement to the init, similar
    // to android - then it doesn't matter if the pre-populated database is not
    // copied over.
    NSLog(@"BEMDataCollection:pluginInitialize singleton -> initialize statemachine and delegate");

    StatsEvent* se = [[StatsEvent alloc] initForEvent:@"app_launched"];
    [[BuiltinUserCache database] putMessage:@"key.usercache.client_nav_event" value:se];

    // NOTE: This CANNOT be part of a background thread because when the geofence creation, and more importantly,
    // the visit notification, are run as part of a background thread, they don't work.
    // I tried to move this into a background thread as part of a18f8f9385bdd9e37f7b412b386a911aee9a6ea0 and had
    // to revert it because even visit notification, which had been the bedrock of my existence so far, stopped
    // working although I made an explicit stop at the education library on the way to Soda.
    NSString* reqConsent = [self settingForKey:@"emSensorDataCollectionProtocolApprovalDate"];
    BOOL isConsented = [ConfigManager isConsented:reqConsent];
    if (isConsented) {
        [self initWithConsent];
    } else {
        [LocalNotificationManager showNotification:@"New data collection terms - collection paused until consent"];
    }
}
shankari commented 8 years ago

Solutions:

So I can definitely add a consent check to the remotePush delegate, and potentially to the visit delegate as well, since that is the one constant in an unfeeling universe.

Should I try to initialize the TripDiaryStateMachine as well? It seems like I should - all of the pre-consent testing had the TripDiaryStateMachine init happening as part of the AppDelegate, IIRC.

But that seems like a pretty big change for now, and the iOS phones seem to be working pretty well for me so far. Should also see when the tracking stopped last time. If we check the consent on plugin load, when did we detect no consent and turn things off?

Tracking worked until this.

768,1475974983.9,2016-10-08 18:56:03.901400-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP" 
769,1475974983.94,2016-10-08 18:56:03.944830-07:00,Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START
820,1475975141.85,2016-10-08 18:58:41.851210-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"

Then the UI launched.

821,1475979151.08,2016-10-08 20:05:31.076470-07:00,finished init of iOS native code
822,1475979151.08,2016-10-08 20:05:31.082440-07:00,truncating obsolete entries before 1473387151.082153
823,1475979153.6,2016-10-08 20:05:33.597220-07:00,About to set theme from preference
824,1475979153.61,2016-10-08 20:05:33.607340-07:00,preferred theme = dark_theme
825,1475979153.61,2016-10-08 20:05:33.614240-07:00,set dark_theme = true
826,1475979153.69,2016-10-08 20:05:33.688110-07:00,About to navigate to preferred tab
827,1475979154.06,2016-10-08 20:05:34.055330-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
828,1475979154.07,2016-10-08 20:05:34.065800-07:00,changing state to root.main.metrics
829,1475979156.11,2016-10-08 20:05:36.113940-07:00,CommunicationHelper.execute called!
830,1475979156.12,2016-10-08 20:05:36.123090-07:00,"currAuth = null, reading the current value from the keychain"
831,1475979156.14,2016-10-08 20:05:36.136370-07:00,"currAuth = GTMOAuth2Authentication 0x1702e5700: {refreshToken=""1/abNzx-3k2gy48HNhmiBmptDpf5NsELbvi7_crr_-g6c""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
832,1475979156.14,2016-10-08 20:05:36.143710-07:00,"token has expired, refreshing it"
833,1475979156.15,2016-10-08 20:05:36.150680-07:00,beginning refresh of token expiring at (null)
834,1475979214.08,2016-10-08 20:06:34.080110-07:00,Ionic Deploy: Update available: false

and then tracking stopped!

836,1476048197.77,2016-10-09 15:16:17.766930-07:00,Application will enter the foreground
837,1476048214.44,2016-10-09 15:16:34.435150-07:00,"after stopping tracking, state is STATE_START"
shankari commented 8 years ago

Only instance of that string in the code is here. So we reconfigured? But then why didn't the restart work? We don't check for consent here?

- (void) restartCollection {
    if (self.tripDiaryStateMachine.currState == kTrackingStoppedState) {
        [LocalNotificationManager addNotification:[NSString stringWithFormat:
                                                   @"in restartCollection, state is already TRACKING_STOPPED, early return"]];
        return;
    }
    [[NSNotificationCenter defaultCenter] postNotificationName:CFCTransitionNotificationName
                                                        object:CFCTransitionForceStopTracking];

    [LocalNotificationManager addNotification:[NSString stringWithFormat:
                                               @"after stopping tracking, state is %@",
                                               [TripDiaryStateMachine getStateName:self.tripDiaryStateMachine.currState]]];

    // This may take a while to complete, but we don't care
    [[NSNotificationCenter defaultCenter] postNotificationName:CFCTransitionNotificationName
                                                         object:CFCTransitionStartTracking];
}
shankari commented 8 years ago

There is also no indication that we received a STOP_TRACKING notification.

821,1475979151.08,2016-10-08 20:05:31.076470-07:00,finished init of iOS native code
822,1475979151.08,2016-10-08 20:05:31.082440-07:00,truncating obsolete entries before 1473387151.082153
823,1475979153.6,2016-10-08 20:05:33.597220-07:00,About to set theme from preference
824,1475979153.61,2016-10-08 20:05:33.607340-07:00,preferred theme = dark_theme
825,1475979153.61,2016-10-08 20:05:33.614240-07:00,set dark_theme = true826,1475979153.69,2016-10-08 20:05:33.688110-07:00,About to navigate to preferred tab
827,1475979154.06,2016-10-08 20:05:34.055330-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
828,1475979154.07,2016-10-08 20:05:34.065800-07:00,changing state to root.main.metrics
829,1475979156.11,2016-10-08 20:05:36.113940-07:00,CommunicationHelper.execute called!
830,1475979156.12,2016-10-08 20:05:36.123090-07:00,"currAuth = null, reading the current value from the keychain"
831,1475979156.14,2016-10-08 20:05:36.136370-07:00,"currAuth = GTMOAuth2Authentication 0x1702e5700: {refreshToken=""1/abNzx-3k2gy48HNhmiBmptDpf5NsELbvi7_crr_-g6c""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"832,1475979156.14,2016-10-08 20:05:36.143710-07:00,"token has expired, refreshing it"
833,1475979156.15,2016-10-08 20:05:36.150680-07:00,beginning refresh of token expiring at (null)
834,1475979214.08,2016-10-08 20:06:34.080110-07:00,Ionic Deploy: Update available: false
835,1475979217.09,2016-10-08 20:06:37.093650-07:00,"Error Error Domain=NSURLErrorDomain Code=-1001 ""The request timed out."" UserInfo={NSUnderlyingError=0x170249d80 {Error Domain=kCFErrorDomainCFNetwork Code=-1001 ""(null)"" UserInfo={_kCFStreamErrorCodeKey=-2102, _kCFStreamErrorDomainKey=4}}, NSErrorFailingURLStringKey=https://www.googleapis.com/oauth2/v4/token, NSErrorFailingURLKey=https://www.googleapis.com/oauth2/v4/token, _kCFStreamErrorDomainKey=4, _kCFStreamErrorCodeKey=-2102, NSLocalizedDescription=The request timed out.} while refreshing token, need to retry"
836,1476048197.77,2016-10-09 15:16:17.766930-07:00,Application will enter the foreground
837,1476048214.44,2016-10-09 15:16:34.435150-07:00,"after stopping tracking, state is STATE_START"
shankari commented 8 years ago

Change to move the TripDiaryStateMachine initialization from didFinishLaunchingWithOptions to pluginInitialize happened back in Feb 2016. We've tested it multiple times since then, so I am not keen to revert it. I will add the consent check and push a new release, and then continue testing to see if the TripDiaryStateMachine init changes have made a difference.

https://github.com/e-mission/e-mission-data-collection/pull/96

shankari commented 8 years ago

Another thing to note wrt the logs in https://github.com/e-mission/e-mission-phone/issues/181#issuecomment-258766187, the app stopped receiving remote push notifications on the 15th, roughly a week after the install.

,ts,dt,message
0,1475866995.87,2016-10-07 12:56:15.865810-07:00,finished init of iOS native code

1084,1476547227.98,2016-10-15 09:53:27.975180-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
1070,1476543605.42,2016-10-15 08:53:05.415710-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
1098,1476550805.36,2016-10-15 10:53:05.363390-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
1105,1476554405.85,2016-10-15 11:53:05.847370-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"

Is that a common pattern? If so, why does it occur.

It looks like as long as the app is launched to deal with location events, the plugin init is called.

As expected, after the 8th, every time we init the code, we change state to metrics.

But sometimes before that, we see this pattern, with no manual init involved.

562,1475913612.19,2016-10-08 01:53:12.189100-07:00,finished init of iOS native code
564,1475913612.27,2016-10-08 01:53:12.267880-07:00,initializing TripDiaryStateMachine with state = STATE_WAITING_FOR_TRIP_START
566,1475913612.58,2016-10-08 01:53:12.577290-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
568,1475913612.65,2016-10-08 01:53:12.648380-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
572,1475913612.74,2016-10-08 01:53:12.740890-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
575,1475913612.79,2016-10-08 01:53:12.793350-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
579,1475913612.9,2016-10-08 01:53:12.900660-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
648,1475913888.53,2016-10-08 01:57:48.527880-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
658,1475913888.67,2016-10-08 01:57:48.667740-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
668,1475913890.8,2016-10-08 01:57:50.804990-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
670,1475913890.95,2016-10-08 01:57:50.953970-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
708,1475913899.54,2016-10-08 01:57:59.537340-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"

Note that sometimes, we handle the location events without the iOS init. I wonder if that is the difference between background -> foreground and killed.

709,1475973760.09,2016-10-08 18:35:40.087690-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
711,1475973760.13,2016-10-08 18:35:40.125140-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START"
715,1475973760.2,2016-10-08 18:35:40.197140-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"
718,1475973760.22,2016-10-08 18:35:40.224250-07:00,"In TripDiaryStateMachine, received transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP"
725,1475973840.26,2016-10-08 18:37:00.262820-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"
751,1475974983.01,2016-10-08 18:56:03.009410-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
756,1475974983.1,2016-10-08 18:56:03.104620-07:00,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
766,1475974983.87,2016-10-08 18:56:03.867870-07:00,"In TripDiaryStateMachine, received transition T_END_TRIP_TRACKING in state STATE_ONGOING_TRIP"
768,1475974983.9,2016-10-08 18:56:03.901400-07:00,"In TripDiaryStateMachine, received transition T_TRIP_ENDED in state STATE_ONGOING_TRIP"
820,1475975141.85,2016-10-08 18:58:41.851210-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
shankari commented 8 years ago

Tried to reproduce the bug by clearing only the usercache from the UI while keeping the localStorage. Left the app running after that with the screen closed. At the next remote push, saw the notification.

On sliding the notification, went back to the consent page of the app. It was now consented (probably because of the sync which pulled from the server).

no_consent_notify_iphone_logs.log.gz

Deleting again and killing the app as well this time.

shankari commented 8 years ago

After deleting and killing the app, did not receive any remote notifications for 5 hours. no_consent_notify_iphone_after_kill.log.gz

shankari commented 8 years ago

wrt https://github.com/e-mission/e-mission-phone/issues/181#issuecomment-258855775, this is expected behavior. But it should be relaunched on geofence exit or significant location changes.

https://developer.apple.com/reference/uikit/uiapplicationdelegate/1623013-application?language=objc

However, the system does not automatically launch your app if the user has force-quit it. In that situation, the user must relaunch your app or restart the device before the system attempts to launch your app automatically again.
shankari commented 8 years ago

wrt https://github.com/e-mission/e-mission-phone/issues/181#issuecomment-258858737

But it should be relaunched on geofence exit or significant location changes.

Yup, it did! It looks like the app was launched and generated the consent required message.

But then it looks like the launch of the UI caused the consent to get overwritten. Because by the time that I came back, the consent was fine again.

Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: Apache Cordova native platform version 4.1.1 is starting.
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: Multi-tasking -> Device: YES, App: YES
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: Using UIWebView
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][handleopenurl] 0.344038ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][intentandnavigationfilter] 6.796002ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][gesturehandler] 0.471950ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][keyboard] 2.927005ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: UnifiedLogger:pluginInitialize singleton -> initialize native DB
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: no cloud sync at path: /var/mobile/Containers/Data/Application/2BF61CF3-AED5-4B2D-94FC-384D311904A1/Library/LocalDatabase
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: INFO: finished init of iOS native code
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: INFO: truncating obsolete entries before 1475944852.275303
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][unifiedlogger] 263.894975ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: BEMUserCache:pluginInitialize singleton -> initialize native DB
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: no cloud sync at path: /var/mobile/Containers/Data/Application/2BF61CF3-AED5-4B2D-94FC-384D311904A1/Library/LocalDatabase
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: Database is <BuiltinUserCache: 0x13452cf10>
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][usercache] 3.107965ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: creating new AuthCompletionHandler sharedInstance
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][jwtauth] 0.744998ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: BEMDataCollection:pluginInitialize singleton -> initialize statemachine and delegate
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: data has 114 bytes, str has size 114
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: DEBUG: reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: isConsented = YES
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: DEBUG: initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP
Nov  7 08:40:52 ucb-sdb-iphone-4 locationd[64] <Notice>: client 'edu.berkeley.eecs.emission' starting significant location changes
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: started fine location tracking with accuracy = -1 and distanceFilter = 50
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: DEBUG: started fine location tracking with accuracy = -1 and distanceFilter = 50
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: Current location authorization = 3, always = 3
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: Initialized remote push notification handler <BEMRemotePushNotificationHandler: 0x1346888e0>, finished registering for notifications
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: DEBUG: Initialized remote push notification handler <BEMRemotePushNotificationHandler: 0x1346888e0>, finished registering for notifications
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][datacollection] 370.804012ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][file] 3.372967ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: VERSION LABEL: 1.4.0:1478501022:
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][ionicdeploy] 0.796020ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][socialsharing] 71.231008ms
Nov  7 08:40:52 ucb-sdb-iphone-4 emission[906] <Warning>: [CDVTimer][TotalPluginStartup] 733.393013ms

no-consent-changed-to-yes-after-restart.log.gz

shankari commented 8 years ago

Ok so the current behavior is:

The one corner case that I can think of is:

Then, we won't get location updates, and we won't get silent push notifications. Probably we should send a real remote push notification in that case, which should cause the user to launch the app (this time with consent turned on) and so then everything should work again.

Will that actually work? Maybe I should just send a non-silent push notification to all users and ask them to check out the leaderboard or something. After I push the update, that should fix all the consent issues...

shankari commented 8 years ago

Let's test that with the following use case:

shankari commented 8 years ago

So I set the sync config = 10 mins, deleted consent and killed the app. Then I left it running for a few hours. As expected, the app was not launched. Instead, we got a bunch of messages like so:

ov  7 12:10:03 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Nov  7 12:20:07 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Nov  7 12:23:41 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Nov  7 12:30:03 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed

which apparently mean that the app was not launched because it was killed. https://forums.developer.apple.com/thread/36776

Now, sending a manual, non-silent notification to the 10 min channel.

That didn't work the first time, but did work the second time.

Nov  7 14:00:08 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Nov  7 14:00:08 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Nov  7 14:01:11 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
shankari commented 8 years ago

the new code also seems to crash a lot

0   libobjc.A.dylib                 0x0000000182545b9c objc_msgSend + 28
1   emission                        0x0000000100167890 -[AppDelegate(notification) launchTripEndCheckAndRemoteSync:] (BEMAppDelegate.m:178)
2   emission                        0x0000000100166e4c -[AppDelegate(notification) application:didReceiveRemoteNotification:fetchCompletionHandler:] (BEMAppDelegate.m:87)
3   UIKit                           0x00000001882d20b8 -[UIApplication _handleNonLaunchSpecificActions:forScene:withTransitionContext:completion:] + 2676
4   UIKit                           0x00000001882bfe94 -[UIApplication workspace:didReceiveActions:] + 136
0   libobjc.A.dylib                 0x0000000182545b9c objc_msgSend + 28
1   emission                        0x000000010016324c -[TripDiaryDelegate locationManager:didVisit:] (TripDiaryDelegate.m:247)
2   CoreLocation                    0x0000000189c1b5dc 0x189c0c000 + 62940
3   CoreLocation                    0x0000000189c14aac 0x189c0c000 + 35500

Going to try to fix that, and then will try option 1 again.

shankari commented 8 years ago

Appear to have fixed it by fixing the method signature. Next step: investigate Sam's log file to see if there's another change we need to squeeze in. Then, test while on the way to/from karate. Then submit fix tonight.

shankari commented 8 years ago

Investigated Sam's log file, not related. That's a different consent issue and is really different from any issue I have seen before.

What I see from the logs is that his data seems to be collected fine until the 21st, but then I get this error.

6876,1477093581.19,2016-10-21 17:39:21.188500-07:00,"New authorization status = 2, always = 3"
6877,1477093581.26,2016-10-21 17:39:21.261360-07:00,"Location tracking failed with error Error Domain=kCLErrorDomain Code=1 ""The operation couldn’t be completed. (kCLErrorDomain error 1.)"""

Then, the app was launched again on the 28th, but the authorization status was still not good enough.

6883,1477689395.14,2016-10-28 15:09:35.138530-07:00,"New authorization status = 2, always = 3"
6884,1477689395.42,2016-10-28 15:09:35.417620-07:00,"Location tracking failed with error Error Domain=kCLErrorDomain Code=1 ""The operation couldn’t be completed. (kCLErrorDomain
 error 1.)"""
6885,1477689395.46,2016-10-28 15:09:35.463490-07:00,"Location tracking failed with error Error Domain=kCLErrorDomain Code=1 ""The operation couldn’t be completed. (kCLErrorDomain error 1.)"""

And then he launched it on the 3rd, at which point it seems to be fine again.

6970,1478204908.04,2016-11-03 14:21:28.042590-07:00,finished init of iOS native code
6975,1478204910.82,2016-11-03 14:21:30.817260-07:00,"New authorization status = 3, always = 3"
6976,1478204911.89,2016-11-03 14:21:31.886450-07:00,"Recieved location <> +/- 65.00m (speed -1.00 mps / course -1.00) @ 11/3/16, 1:28:28 PM Pacific Daylight Time, ongoing trip = true"
shankari commented 8 years ago

I looked at the source code and 2 is denied.

typedef NS_ENUM(int, CLAuthorizationStatus) {
    // User has not yet made a choice with regards to this application
    kCLAuthorizationStatusNotDetermined = 0,

    // This application is not authorized to use location services.  Due
    // to active restrictions on location services, the user cannot change
    // this status, and may not have personally denied authorization
    kCLAuthorizationStatusRestricted,

    // User has explicitly denied authorization for this application, or
    // location services are disabled in Settings.
    kCLAuthorizationStatusDenied,

    // User has granted authorization to use their location at any time,
    // including monitoring for regions, visits, or significant location changes.
    kCLAuthorizationStatusAuthorizedAlways NS_ENUM_AVAILABLE(NA, 8_0),
shankari commented 8 years ago

denied for this service, or in settings. unsure what to do with this. probably the best thing to do is to send a push notification requesting you to turn on again. We should also probably log a client error for this.

I will deal with that as part of the next change since I want to keep this change as simple as possible.

shankari commented 8 years ago

Final test before the kids get here.

shankari commented 8 years ago

Check again now

Tried this a couple of more times - they were successful. Probably ready to submit to the store now...

shankari commented 7 years ago

Just for completeness, I looked at what would happen on android in a similar situation. The steps were:

However, everything was fine. We didn't even get the alert because the sync pulled the config from the server.

logcat.log.gz

shankari commented 7 years ago

Seems to be fixed now.

MythriNagaraju commented 5 years ago

I probably should not be commenting on a closed issue - but is there a way to completely delete the consent process? Since I could not find a simple way to do this in my custom client, I marked consent in the code, but it still expects user consent to re-start data collection when data collection is paused. What are the different scenarios when data collection is paused? Sorry if my questions are redundant. It would be of great help if you could point me to related issues/relevant documentation.

shankari commented 5 years ago

@MythriNagaraju yeah can you just file a new issue? Maybe with a subject like "How to skip the consent screen in the UI?" Would also be great if you could provide more details - e.g.