search

e-mission / cordova-jwt-auth

BSD 3-Clause "New" or "Revised" License
2 stars 9 forks source link

Login consistently fails with error "Could not determine client ID from request." #8

Closed shankari closed 7 years ago

shankari commented 7 years ago

This was reported multiple times during the last round of testing, but no amount of poring through the logs could figure out why. But now I am miraculously stuck in that state in debug mode. So I can attach the debugger and figure out what's going on and how to fix it.

First, it is not a server side issue. Looking at the history of post and get calls, there isn't anything related to the metrics or the diary. So this must be an error in generating the token.

ubuntu@ip-10-203-173-119:/mnt/logs/emission$ bzgrep "START GET" webserver.log.gz | tail 
2016-10-25 05:33:38,389:DEBUG:139992269563648:START GET /img/GitHub-Mark-120px-plus.png
2016-10-25 05:33:38,390:DEBUG:139992261170944:START GET /img/personal/compare_with_common.png
2016-10-25 05:33:38,394:DEBUG:139992311527168:START GET /img/personal/list_view.png
2016-10-25 05:33:38,396:DEBUG:139992535529216:START GET /img/personal/detail_view.png
2016-10-25 05:33:38,399:DEBUG:139992303134464:START GET /img/personal/common_trips.png
2016-10-25 05:33:38,401:DEBUG:139992543921920:START GET /img/apple-badge.svg
2016-10-25 05:33:38,525:DEBUG:139992269563648:START GET /img/aggregate/bike_march_2016.png
2016-10-25 05:33:38,623:DEBUG:139992543921920:START GET /img/aggregate/bike_apr_2016.png
2016-10-25 05:33:41,184:DEBUG:139992543921920:START GET /img/favicon-96x96.png
2016-10-25 06:35:25,101:DEBUG:139992277956352:START GET /redirect/join

ubuntu@ip-10-203-173-119:/mnt/logs/emission$ bzgrep "START POST" webserver.log.gz | tail
2016-10-25 07:00:15,812:DEBUG:139992294741760:START POST /usercache/get
2016-10-25 07:00:16,148:DEBUG:139992535529216:START POST /stats/set
2016-10-25 07:03:23,453:DEBUG:139992311527168:START POST /usercache/put
2016-10-25 07:03:25,674:DEBUG:139992269563648:START POST /usercache/get
2016-10-25 07:03:29,615:DEBUG:139992277956352:START POST /stats/set
2016-10-25 07:06:30,429:DEBUG:139992261170944:START POST /usercache/put
2016-10-25 07:06:33,179:DEBUG:139992543921920:START POST /usercache/get
2016-10-25 07:06:36,010:DEBUG:139992286349056:START POST /stats/set
2016-10-25 07:08:15,630:DEBUG:139992527136512:START POST /usercache/get
2016-10-25 07:08:16,556:DEBUG:139992303134464:START POST /stats/set
shankari commented 7 years ago

Adding debugging shows that the error is generated here.

    [oldAuth authorizeRequest:NULL completionHandler:^(NSError *error) {
        GTMOAuth2Authentication* newAuth = self.currAuth;
                    if (error != NULL) {
            [LocalNotificationManager addNotification:[NSString stringWithFormat:
                                                       @"Error %@ while refreshing token, need to retry", error] showUI:TRUE];
                        // modify some kind of error count and notify that user needs to sign in again
                        authCompletionCallback(NULL, error);
                    } else {
shankari commented 7 years ago

but why is the clientID invalid? Or is it?

shankari commented 7 years ago

while refreshing the token, the oldAuth is shown below. Note that both clientID and clientSecret are null.

oldAuth GTMOAuth2Authentication *   0x1546139e0 0x00000001546139e0
NSObject    NSObject    
clientID_   NSString *  nil 0x0000000000000000
clientSecret_   NSString *  nil 0x0000000000000000
redirectURI_    __NSCFConstantString *  @"urn:ietf:wg:oauth:2.0:oob"    0x00000001002f2ac0
parameters_ __NSDictionaryM *   6 key/value pairs   0x0000000154641540
tokenURL_   NSURL * @"https://www.googleapis.com/oauth2/v4/token"   0x0000000154641490
expirationDate_ NSDate *    nil 0x0000000000000000
authorizationTokenKey_  NSString *  nil 0x0000000000000000
additionalTokenRequestParameters_   NSDictionary *  nil 0x0000000000000000
additionalGrantTypeRequestParameters_   NSDictionary *  nil 0x0000000000000000
refreshFetcher_ GTMSessionFetcher * nil 0x0000000000000000
authorizationQueue_ __NSArrayM *    @"0 elements"   0x0000000154613a60
fetcherService_ id  0x0 0x0000000000000000
shouldAuthorizeAllRequests_ BOOL    NO  false
userData_   id  0x0 0x0000000000000000
properties_ NSMutableDictionary *   nil 0x0000000000000000
shankari commented 7 years ago

Doing some searching for the error message, Could not determine client ID from request we get https://github.com/google/google-api-objectivec-client-for-rest/issues/35

which claims that if you are killed (as opposed to quit) then you get this error.

Trial and error taught me that when you stop the app and restart it but remain logged in to your Google account this error happens. When I enter the client ID followed by signing into Google, it works.

shankari commented 7 years ago

Couple of more observations. Note that all fields of the oldAuth are NULL. We can see this from the logs as well.

Oct 25 00:14:31 ucb-sdb-iphone-4 emission[1512] <Warning>: currAuth != null, nothing to do
Oct 25 00:14:47 ucb-sdb-iphone-4 emission[1512] <Warning>: currAuth = GTMOAuth2Authentication 0x1546139e0: {refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES
Oct 25 00:14:49 ucb-sdb-iphone-4 emission[1512] <Warning>: token has expired, refreshing it

So basically the auth we read from the keychain is completely empty, and has no clientID either. That is why the clientID is invalid and we are unable to get a token.

Note also that when I connect with XCode, and following Devices -> (sel phone) -> View Device Logs, I see two "Crashes". The backtraces are as below, so I am not sure whether this is a crash or not.

Several observations:

Incident Identifier: 62816280-AE4D-4893-A5DD-7488BCAC6179
CrashReporter Key:   fe64d46fae153cdcadc5fa3c84dcfeb190509f12
Hardware Model:      iPhone7,2
Process:             emission [1441]
Path:                /var/containers/Bundle/Application/77E1AEA4-316E-4A25-A8CE-13101E5AD369/emission.app/emission
Identifier:          edu.berkeley.eecs.emission
Version:             15 (1.2.0)
Code Type:           ARM-64 (Native)
Parent Process:      launchd [1]

Date/Time:           2016-10-23 07:41:00.00 -0700
Launch Time:         2016-10-23 00:13:30.30 -0700
OS Version:          iOS 9.3 (13E233)
Report Version:      105

Exception Type:  00000020
Exception Codes: 0x000000008badf00d
Exception Note:  SIMULATED (this is NOT a crash)
Highlighted by Thread:  0

Application Specific Information:
<BKNewProcess: 0x124d36b10; edu.berkeley.eecs.emission; pid: 1441; hostpid: -1> has active assertions beyond permitted time: 
{(
    <BKProcessAssertion: 0x124d24fc0> id: 58-E68875EF-AA92-464E-99CA-734B72AD078D name: Background Content Fetching (970) process: <BKNewProcess: 0x124d36b10; edu.berkeley.eecs.emission; pid: 1441; hostpid: -1> permittedBackgroundDuration: 30.000000 reason: backgroundContentFetching owner pid:58 preventSuspend  preventThrottleDownUI  preventIdleSleep  preventSuspendOnSleep ,
    [several more of these]
    <BKProcessAssertion: 0x124d389f0> id: 58-FD4B3BD0-A846-4074-849A-E1C50F8F72AF name: Background Content Fetching (968) process: <BKNewProcess: 0x124d36b10; edu.berkeley.eecs.emission; pid: 1441; hostpid: -1> permittedBackgroundDuration: 30.000000 reason: backgroundContentFetching owner pid:58 preventSuspend  preventThrottleDownUI  preventIdleSleep  preventSuspendOnSleep ,
    <BKProcessAssertion: 0x124d1dff0> id: 58-E7459438-DDD2-45BD-ACBB-9953A36C7559 name: Background Content Fetching (953) process: <BKNewProcess: 0x124d36b10; edu.berkeley.eecs.emission; pid: 1441; hostpid: -1> permittedBackgroundDuration: 30.000000 reason: backgroundContentFetching owner pid:58 preventSuspend  preventThrottleDownUI  preventIdleSleep  preventSuspendOnSleep 
)}

Elapsed total CPU time (seconds): 0.010 (user 0.010, system 0.000), 100% CPU 
Elapsed application CPU time (seconds): 0.000, 2% CPU
Incident Identifier: 7B1215E4-C30D-46AC-976F-6A6EFB2B67F2
CrashReporter Key:   fe64d46fae153cdcadc5fa3c84dcfeb190509f12
Hardware Model:      iPhone7,2
Process:             emission [1470]
Path:                /var/containers/Bundle/Application/77E1AEA4-316E-4A25-A8CE-13101E5AD369/emission.app/emission
Identifier:          edu.berkeley.eecs.emission
Version:             15 (1.2.0)
Code Type:           ARM-64 (Native)
Parent Process:      launchd [1]

Date/Time:           2016-10-24 08:55:02.02 -0700
Launch Time:         2016-10-23 08:00:09.09 -0700
OS Version:          iOS 9.3 (13E233)
Report Version:      105

Exception Type:  00000020
Exception Codes: 0x000000008badf00d
Exception Note:  SIMULATED (this is NOT a crash)
Highlighted by Thread:  7

Application Specific Information:
<BKNewProcess: 0x124e1fa20; edu.berkeley.eecs.emission; pid: 1470; hostpid: -1> has active assertions beyond permitted time: 
{(
    <BKProcessAssertion: 0x124d20e00> id: 1470-B2C7F2F1-FD65-4499-951C-D81431DE2EF9 name: GTMSessionFetcher-e-mission.eecs.berkeley.edu process: <BKNewProcess: 0x124e1fa20; edu.berkeley.eecs.emission; pid: 1470; hostpid: -1> permittedBackgroundDuration: 180.000000 reason: finishTask owner pid:1470 preventSuspend  preventIdleSleep  preventSuspendOnSleep 
)}

Elapsed total CPU time (seconds): 13.120 (user 13.120, system 0.000), 5% CPU 
Elapsed application CPU time (seconds): 2.358, 1% CPU

Filtered syslog:
None found
shankari commented 7 years ago

Copies of the logs + "crash" backtraces.

crash_stacktrace_1.gz crash_stacktrace_2.gz iphone-login-crash.gz

shankari commented 7 years ago

It seems pretty clear what is happening here.

shankari commented 7 years ago

It looks like there are multiple fixes:

Note that, unlike I had originally thought, we cannot just reset the clientID if it is NULL because the refreshToken is also NULL, so the auth would fail anyway.

shankari commented 7 years ago

Note that, unlike I had originally thought, we cannot just reset the clientID if it is NULL because the refreshToken is also NULL, so the auth would fail anyway.

I should actually try this out on the phone with the corrupted token

shankari commented 7 years ago

emission logs: loggerDB.iphone.broken_login.gz

shankari commented 7 years ago

From the e-mission logs, https://github.com/e-mission/cordova-jwt-auth/issues/8#issuecomment-256087041 does not appear to be the case. In particular, the last reported "crash" was at 8:55, but the data was actually completely pushed by 8:53.

4664,1477321208.61,2016-10-24 08:53:08.608510-07:00,"In TripDiaryStateMachine, received transition T_RECEIVED_SILENT_PUSH in state STATE_WAITING_FOR_TRIP_START"
4665,1477321208.65,2016-10-24 08:53:08.649760-07:00,backgroundSync called
4666,1477321208.68,2016-10-24 08:53:08.677620-07:00,pushAndClearUserCache called
4667,1477321208.69,2016-10-24 08:53:08.691550-07:00,"lastTripEndTs = -1.000000, nothing to push, returning"
4668,1477321208.71,2016-10-24 08:53:08.706570-07:00,"locEntriesToPush count == 0, returning "
4673,1477321208.79,2016-10-24 08:53:08.792850-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {accessToken=""ya29.CjCGA8ZnBtL0w6TG19JeI6DhcZZ-u8KBU9qCz9On9-k1TjrRpxdDrZJGrPoBH5k5JdY"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-24 15:00:09 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-24 15:00:09 +0000, expired = NO"
4699,1477321219.14,2016-10-24 08:53:19.140610-07:00,Retrieved 8 documents
4700,1477321219.18,2016-10-24 08:53:19.177910-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
4701,1477321219.23,2016-10-24 08:53:19.227840-07:00,Received notification T_DATA_PUSHED while processing silent push notification
4702,1477321219.25,2016-10-24 08:53:19.249580-07:00,"Data pushed, fetch result = new data"

A subsequent call at 9:44 was successful (although note that the token did not need to be refreshed since it was valid)

4717,1477322602.09,2016-10-24 09:16:22.088620-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
...
4768,1477324311.15,2016-10-24 09:44:51.147840-07:00,"Received visit notification = <+37.40370981,-122.08416323> +/- 35.71m (2016-10-24 15:31:51 +0000 to -)"
4769,1477324311.17,2016-10-24 09:44:51.167290-07:00,"departure date is 4001-01-01 00:00:00 +0000, isDistantDate? 1, after distantDate? 0 "
4770,1477324311.19,2016-10-24 09:44:51.190190-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"
4772,1477324311.26,2016-10-24 09:44:51.262630-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {accessToken=""ya29.CjCGA8lg13imwXQEjXj-VEY0BkL_WJU6kxyPkNs8EKMynXPHfWnvddI_f4HXnktDikU"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-24 16:00:08 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-24 16:00:08 +0000, expired = NO"
4796,1477324312.48,2016-10-24 09:44:52.477140-07:00,Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START
4797,1477324312.5,2016-10-24 09:44:52.498080-07:00,backgroundSync called
4808,1477324312.82,2016-10-24 09:44:52.823090-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {accessToken=""ya29.CjCGA8lg13imwXQEjXj-VEY0BkL_WJU6kxyPkNs8EKMynXPHfWnvddI_f4HXnktDikU"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-24 16:00:08 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-24 16:00:08 +0000, expired = NO"
4838,1477324368.73,2016-10-24 09:45:48.732920-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"

And then, finally, at 9:53, we get a background sync call (through a push notification, I presume) and then when we read the data, it is all null.

4841,1477324813.71,2016-10-24 09:53:13.712840-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
4842,1477324813.73,2016-10-24 09:53:13.730170-07:00,"currAuth = null, reading the current value from the keychain"
4843,1477324813.76,2016-10-24 09:53:13.760160-07:00,"currAuth = GTMOAuth2Authentication 0x1546139e0: {refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
shankari commented 7 years ago

I am so glad that I did!

It turns out that self.clientId and self.clientSecret are also NULL. That explains why the token has all null values. If I don't have the auth to read the keychain, I sure as hell don't want to be given the refresh token.

But IIRC, the clientId and clientSecret are read from a plist file. Why TF are they null?!

self    AuthCompletionHandler * 0x15fdc48f0 0x000000015fdc48f0
NSObject    NSObject    
listeners   __NSArrayM *    @"0 elements"   0x000000015fdc4930
_currAuth   GTMOAuth2Authentication *   0x15fdd38d0 0x000000015fdd38d0
_errorArray NSMutableArray *    nil 0x0000000000000000
_scope  NSString *  nil 0x0000000000000000
_clientId   NSString *  nil 0x0000000000000000
_clientSecret   NSString *  nil 0x0000000000000000
shankari commented 7 years ago

from https://github.com/e-mission/cordova-jwt-auth/issues/8#issuecomment-256124165,

why TF are they null?!

because they are set in BEMAppDelegate.didFinishLaunchingWithOptions and that is never called.

@implementation AppDelegate (notification)

+ (BOOL)didFinishLaunchingWithOptions:(NSDictionary *)launchOptions {
...
    // Handle google+ sign on
    [AuthCompletionHandler sharedInstance].clientId = [[ConnectionSettings sharedInstance] getGoogleiOSClientID];
    [AuthCompletionHandler sharedInstance].clientSecret = [[ConnectionSettings sharedInstance] getGoogleiOSClientSecret];
    return YES;
}

The breakpoints on launch are:

So we call BEMAppDelegate.didFinishLaunchingWithOptions from the pluginInitialize method of the DataCollectionPlugin. And it is still set to run onLoad. Why isn't the method being called?

shankari commented 7 years ago

Why isn't the method being called?

Because isConsent returns false.

- (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");
    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 7 years ago

And that's because getDocument returns NULL with key = @"key.usercache.consent_config

-(NSObject*) getDocument:(NSString*)key wrapperClass:(Class)cls {
    NSString* dataStr = [self getDocumentStringOrEntry:[self getStatName:key] withMetadata:NO];
    if (dataStr != NULL) {
        return [DataUtils stringToWrapper:dataStr wrapperClass:cls];
    }
    return NULL;
}
shankari commented 7 years ago

Right before everything broke, we had 8 documents in the cache

4821,1477324333.83,2016-10-24 09:45:13.827010-07:00,"currDoc has keys (
)
...
4828,1477324333.96,2016-10-24 09:45:13.964750-07:00,"currDoc has keys (
)
4829,1477324334.26,2016-10-24 09:45:14.260640-07:00,Retrieved 8 documents

But probably due running the push and pull in parallel, we cleared the cache AFTER the pull. So if pull finishes before push, we lose the consent document and stop syncing further.

4830,1477324368.23,2016-10-24 09:45:48.234470-07:00,successfully pushed 362 entries to the server
4831,1477324368.26,2016-10-24 09:45:48.258250-07:00,clearing overridden rw-documents

Let us see if:

shankari commented 7 years ago

what is in the usercache now

From the UI, only one transition at 8:52, and nothing else. Makes sense - if the consent was turned off, we would not collect any data. This also indicates that this is not the same error as the upgrade to 1.0, since at that time, data collection continued although the login failed.

shankari commented 7 years ago

After exporting from the usercache, we find this.

sqlite> select count(*) from userCache;
2
sqlite> select * from userCache;
1477324368.75384||America/Los_Angeles|message|statemachine/transition||{"currState":"STATE_WAITING_FOR_TRIP_START","transition":"T_DATA_PUSHED"}
1477324368.77278||America/Los_Angeles|message|background/battery||{"battery_status":1,"battery_level_ratio":1}
shankari commented 7 years ago

we have seen this (push after pull) happen before

This actually seems to be more common than not

2013,1477206860.86,2016-10-23 01:07:20.864240-07:00,Retrieved 7 documents
2015,1477206861.17,2016-10-23 01:07:21.171010-07:00,successfully pushed 365 entries to the server
2020,1477206861.27,2016-10-23 01:07:21.266790-07:00,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
2021,1477206902.81,2016-10-23 01:08:02.810940-07:00,"After clear complete, cache has 3 entries"
2098,1477207805.8,2016-10-23 01:23:05.802290-07:00,Retrieved 7 documents
2099,1477207806.05,2016-10-23 01:23:06.051700-07:00,successfully pushed 391 entries to the server
2104,1477207806.23,2016-10-23 01:23:06.228620-07:00,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
2105,1477207822.26,2016-10-23 01:23:22.257070-07:00,"After clear complete, cache has 2 entries"
2654,1477242659.74,2016-10-23 11:03:59.741240-07:00,Retrieved 7 documents
2655,1477242663.59,2016-10-23 11:04:03.592030-07:00,successfully pushed 874 entries to the server
2660,1477242663.74,2016-10-23 11:04:03.740700-07:00,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
2661,1477242663.78,2016-10-23 11:04:03.780280-07:00,"After clear complete, cache has 0 entries"
2746,1477244941.25,2016-10-23 11:42:01.253750-07:00,Retrieved 7 documents
2747,1477244941.33,2016-10-23 11:42:01.325510-07:00,successfully pushed 139 entries to the server
2752,1477244941.44,2016-10-23 11:42:01.438910-07:00,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
2753,1477244941.48,2016-10-23 11:42:01.478850-07:00,"After clear complete, cache has 0 entries"

So why didn't this fail before?

shankari commented 7 years ago

So why didn't this fail before?

I have no idea.

We have zero entries in the cache.

2661,1477242663.78,2016-10-23 11:04:03.780280-07:00,"After clear complete, cache has 0 entries"
2662,1477242663.8,2016-10-23 11:04:03.800040-07:00,Returning with fetch result = new data
2663,1477242663.82,2016-10-23 11:04:03.821530-07:00,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
2664,1477242663.88,2016-10-23 11:04:03.877110-07:00,Received notification T_DATA_PUSHED while processing silent push notification
2665,1477242663.89,2016-10-23 11:04:03.893980-07:00,"Data pushed, fetch result = new data"

We got a geofence exit.

2666,1477243437.21,2016-10-23 11:16:57.205390-07:00,"In TripDiaryStateMachine, received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START"
2671,1477243437.69,2016-10-23 11:16:57.687240-07:00,"Considering region with id = STATIONARY_GEOFENCE_LOCATION, location -122.042817, 37.321115"
2672,1477243437.71,2016-10-23 11:16:57.706720-07:00,Deleting it!!
2673,1477243437.74,2016-10-23 11:16:57.740240-07:00,"In TripDiaryStateMachine, received transition T_TRIP_STARTED in state STATE_ONGOING_TRIP"

We got locations.

2680,1477243438.02,2016-10-23 11:16:58.018730-07:00,"Recieved location <+37.32310630,-122.04164659> +/- 73.21m (speed -1.00 mps / course -1.00) @ 10/23/16, 10:23:57 AM Pacific Daylight Time, ongoing trip = true"
2681,1477243438.09,2016-10-23 11:16:58.085250-07:00,"Received visit notification = <+37.32095817,-122.04266703> +/- 23.55m (2016-10-23 16:50:53 +0000 to 2016-10-23 17:11:01 +0000)"

We got a trip start (visit end)

2682,1477243438.1,2016-10-23 11:16:58.103570-07:00,"departure date is 2016-10-23 17:11:01 +0000, isDistantDate? 0, after distantDate? -1 "
2683,1477243438.13,2016-10-23 11:16:58.125150-07:00,"In TripDiaryStateMachine, received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP"

Some more locations

2685,1477243440.0,2016-10-23 11:16:59.995720-07:00,"Recieved location <+37.32111584,-122.04236970> +/- 30.00m (speed 0.00 mps / course -1.00) @ 10/23/16, 10:23:59 AM Pacific Daylight Time, ongoing trip = true"

Got trip end (visit start)

2686,1477244937.16,2016-10-23 11:41:57.158540-07:00,"Received visit notification = <+37.32093370,-122.04268383> +/- 4.74m (2016-10-23 17:28:57 +0000 to -)"
2687,1477244937.18,2016-10-23 11:41:57.178820-07:00,"departure date is 4001-01-01 00:00:00 +0000, isDistantDate? 1, after distantDate? 0 "
2688,1477244937.2,2016-10-23 11:41:57.199760-07:00,"In TripDiaryStateMachine, received transition T_VISIT_STARTED in state STATE_ONGOING_TRIP"

Was able to re-read the auth, which wasn't expired.

2689,1477244937.26,2016-10-23 11:41:57.255740-07:00,"currAuth != null, nothing to do"
2690,1477244937.28,2016-10-23 11:41:57.279130-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {accessToken=""ya29.CjCFA3QsA7bSCjIHRWsZeTnmSNN55durIbMVbT6l3whTP20Uc6gE-fHxWBpdTHv8AMk"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-23 18:00:03 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-23 18:00:03 +0000, expired = NO"

This has even happened before but we were able to recover!

1908,1477206007.19,2016-10-23 00:53:07.191700-07:00,"currAuth = GTMOAuth2Authentication 0x13817ca70: {accessToken=""ya29.CjCFAzquA2FHHEnSTT7vuwA_E20nwRBUKTjQSVs_MCmQa3Hs3UW_WsMZTQzB_EeW-PE"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", code=""4/jsr9GOvIbtSsptffjUtIbuLPUnzWx0V-Ze7mBntws-8"", expirationDate=""2016-10-23 06:00:04 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-23 06:00:04 +0000, expired = YES"
1978,1477206823.99,2016-10-23 01:06:43.989130-07:00,"currAuth = GTMOAuth2Authentication 0x131006ad0: {refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
2213,1477234810.83,2016-10-23 08:53:10.825330-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
2325,1477238412.85,2016-10-23 09:53:12.851750-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {accessToken=""ya29.CjCFA9ADU6nlMk79myVrakAEypETk6rSR4RHDfunt0IBOzI59IvCoNsC5FcfqdAfmys"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-23 16:00:11 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-23 16:00:11 +0000, expired = YES"

Let's see how we were able to recover! Was this just because we continued in the background, versus the most recent call in the foreground?

shankari commented 7 years ago

Let's see how we were able to recover! Was this just because we continued in the background, versus the most recent call in the foreground?

Get after push.

1953,1477206010.05,2016-10-23 00:53:10.045720-07:00,Retrieved 7 documents

Opened from the UI.

1973,1477206822.7,2016-10-23 01:06:42.701430-07:00,About to navigate to preferred tab
1974,1477206822.94,2016-10-23 01:06:42.942240-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
1975,1477206822.96,2016-10-23 01:06:42.956930-07:00,changing state to root.main.metrics
1976,1477206823.96,2016-10-23 01:06:43.957510-07:00,CommunicationHelper.execute called!
1977,1477206823.97,2016-10-23 01:06:43.971390-07:00,"currAuth = null, reading the current value from the keychain"
1978,1477206823.99,2016-10-23 01:06:43.989130-07:00,"currAuth = GTMOAuth2Authentication 0x131006ad0: {refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"

Then a bunch of un-expired accesses.

1990,1477206859.14,2016-10-23 01:07:19.138530-07:00,"currAuth != null, nothing to do"
1991,1477206859.16,2016-10-23 01:07:19.156180-07:00,"currAuth = GTMOAuth2Authentication 0x131006ad0: {accessToken=""ya29.CjCFA4ARqrtRTbPFU92Jx9G8lR_8qxmLz31d9mEZGp41iVjwNw-HNHVhz0yY-U-E3Tk"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-23 08:13:44 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-23 08:13:44 +0000, expired = NO"
...
2176,1477209605.6,2016-10-23 01:53:05.596620-07:00,"currAuth = GTMOAuth2Authentication 0x131006ad0: {accessToken=""ya29.CjCFA4ARqrtRTbPFU92Jx9G8lR_8qxmLz31d9mEZGp41iVjwNw-HNHVhz0yY-U-E3Tk"", refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"", expirationDate=""2016-10-23 08:13:44 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-23 08:13:44 +0000, expired = NO"

Then a sync in which we deleted everything except 3 entries (I wonder which three those were, maybe the consent was included).

2013,1477206860.86,2016-10-23 01:07:20.864240-07:00,Retrieved 7 documents
2020,1477206861.27,2016-10-23 01:07:21.266790-07:00,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
2021,1477206902.81,2016-10-23 01:08:02.810940-07:00,"After clear complete, cache has 3 entries"

Then a sync with only 2 entries left.

2098,1477207805.8,2016-10-23 01:23:05.802290-07:00,Retrieved 7 documents
2105,1477207822.26,2016-10-23 01:23:22.257070-07:00,"After clear complete, cache has 2 entries"

Then a sync with a big gap between the sync start and end (was I connected to a debugger or something?).

2115,1477209604.45,2016-10-23 01:53:04.453120-07:00,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
2204,1477209635.19,2016-10-23 01:53:35.194400-07:00,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
2205,1477233660.8,2016-10-23 08:34:00.796870-07:00,"After clear complete, cache has 2 entries"

Then a background sync, so a separate thread. So why is this even running?

2212,1477234810.79,2016-10-23 08:53:10.791140-07:00,"currAuth = null, reading the current value from the keychain"
2213,1477234810.83,2016-10-23 08:53:10.825330-07:00,"currAuth = GTMOAuth2Authentication 0x12569f780: {refreshToken=""1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
2214,1477234810.85,2016-10-23 08:53:10.845680-07:00,"token has expired, refreshing it"
2215,1477234810.86,2016-10-23 08:53:10.864700-07:00,beginning refresh of token expiring at (null)
2228,1477234811.5,2016-10-23 08:53:11.503660-07:00,"Finished refreshing token in background, new expiry is 2016-10-23 16:00:11 +0000"
shankari commented 7 years ago

The fix is fairly simple - we just clear the entries after the push and the documents before the pull. That is actually a good fix for the android side too, just in case I try to parallelize that.

I am still worried about not understanding the refresh/consent behavior, so will add additional logging for it just in case it recurs. Will try to repro for the rest of today to understand better and then deploy the change.

shankari commented 7 years ago

Used force sync. It was successful. no push but pull, so we have a consent doc again. So everything started working again.

Logs from the force sync.

Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: backgroundSync called
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: INFO: backgroundSync called
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: pushAndClearUserCache called
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: DEBUG: pushAndClearUserCache called
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: selectQuery = SELECT write_ts FROM userCache WHERE key = 'statemachine/transition' AND data LIKE  '%_transition_:_T_TRIP_ENDED_%' ORDER BY write_ts DESC LIMIT 1
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: There are no T_TRIP_ENDED entries in the usercache. A sync must have just completed.
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: lastTripEndTs = -1.000000, nothing to push, returning
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: locEntriesToPush count == 0, returning 
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: pullIntoUserCache called
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: about to launch remote call for server_to_phone
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: CommunicationHelper.server_to_phone called!
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: CommunicationHelper.execute called!
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: currAuth != null, nothing to do
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: currAuth = GTMOAuth2Authentication 0x14f821aa0: {accessToken="ya29.CjCHA8fzv3SVb8PMTPUFop2Ey3OllTRs3rm5ly0OIlqVpLASeHV2Zc_KUNk_xDt68bI", refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4", expirationDate="2016-10-25 22:00:10 +0000"}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-25 22:00:10 +0000, expired = NO
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: DEBUG: currAuth = GTMOAuth2Authentication 0x14f821aa0: {accessToken="ya29.CjCHA8fzv3SVb8PMTPUFop2Ey3OllTRs3rm5ly0OIlqVpLASeHV2Zc_KUNk_xDt68bI", refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4", expirationDate="2016-10-25 22:00:10 +0000"}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-25 22:00:10 +0000, expired = NO
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: token is valid, returning it
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: DEBUG: token is valid, returning it
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: postToHost called with url = /usercache/get -- https://e-mission.eecs.berkeley.edu
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: CommunicationHelper.execute called!
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: currAuth != null, nothing to do
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: currAuth = GTMOAuth2Authentication 0x14f821aa0: {accessToken="ya29.CjCHA8fzv3SVb8PMTPUFop2Ey3OllTRs3rm5ly0OIlqVpLASeHV2Zc_KUNk_xDt68bI", refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4", expirationDate="2016-10-25 22:00:10 +0000"}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-25 22:00:10 +0000, expired = NO
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: DEBUG: currAuth = GTMOAuth2Authentication 0x14f821aa0: {accessToken="ya29.CjCHA8fzv3SVb8PMTPUFop2Ey3OllTRs3rm5ly0OIlqVpLASeHV2Zc_KUNk_xDt68bI", refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4", expirationDate="2016-10-25 22:00:10 +0000"}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-25 22:00:10 +0000, expired = NO
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: token is valid, returning it
Oct 25 14:37:40 ucb-sdb-iphone-4 emission[1662] <Warning>: DEBUG: token is valid, returning it
Oct 25 14:37:41 ucb-sdb-iphone-4 emission[1662] <Warning>: received response for server_to_phone
Oct 25 14:37:41 ucb-sdb-iphone-4 emission[1662] <Warning>: Got non NULL data while retrieving data
Oct 25 14:37:41 ucb-sdb-iphone-4 emission[1662] <Warning>: currDoc has keys (
Oct 25 14:37:42 ucb-sdb-iphone-4 emission[1662] <Warning>: currDoc has keys (
...
Oct 25 14:37:42 ucb-sdb-iphone-4 emission[1662] <Warning>: currDoc has keys (
Oct 25 14:37:42 ucb-sdb-iphone-4 emission[1662] <Warning>: Retrieved 9 documents
Oct 25 14:37:42 ucb-sdb-iphone-4 emission[1662] <Warning>: all sync completed
shankari commented 7 years ago

I'm going to add more/better logs, and then take a short trip to try and understand what's going on better. Then it is time to fix the underlying code and move on.

shankari commented 7 years ago

Ok, so I can sort of reproduce this by using the "Nuke all buffers and cache" option. With that, the cache gets completely cleared. But doing a force sync works anyway.

Oct 25 16:41:52 ucb-sdb-iphone-4 emission[1677] <Warning>: THREAD WARNING: ['UserCache'] took '20.871094' ms. Plugin should use a background thread.

But not expired, so works

Oct 25 16:42:11 ucb-sdb-iphone-4 emission[1677] <Warning>: backgroundSync called
Oct 25 16:42:11 ucb-sdb-iphone-4 emission[1677] <Warning>: INFO: backgroundSync called
Oct 25 16:42:11 ucb-sdb-iphone-4 emission[1677] <Warning>: pushAndClearUserCache called
Oct 25 16:42:11 ucb-sdb-iphone-4 emission[1677] <Warning>: DEBUG: pushAndClearUserCache called
Oct 25 16:42:11 ucb-sdb-iphone-4 emission[1677] <Warning>: currAuth = GTMOAuth2Authentication 0x127a622f0: {accessToken="ya29.CjCHAzcF9h5PQSEGScAd-3yPUubz60VKNNpMHar0vY20_VhyNXk-xyI0dfuUaHPInkc", refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4", expirationDate="2016-10-25 23:52:13 +0000"}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-25 23:52:13 +0000, expired = NO
shankari commented 7 years ago

what happens if it is expired. Let's retry, including one with killing and restarting (which should make currAuth == NULL.

Expired but not killed

Expired, but apparently not killed, so clientID and secret were still in memory and refresh worked.

Oct 25 17:00:04 ucb-sdb-iphone-4 emission[1677] <Warning>: DEBUG: Received background sync call when useRemotePush = 1, about to check whether a trip has ended
Oct 25 17:00:04 ucb-sdb-iphone-4 emission[1677] <Warning>: About to check whether a trip has ended
Oct 25 17:00:04 ucb-sdb-iphone-4 emission[1677] <Warning>: currAuth != null, nothing to do
Oct 25 17:00:04 ucb-sdb-iphone-4 emission[1677] <Warning>: currAuth = GTMOAuth2Authentication 0x127a622f0: {accessToken="ya29.CjCHAzcF9h5PQSEGScAd-3yPUubz60VKNNpMHar0vY20_VhyNXk-xyI0dfuUaHPInkc", refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4", expirationDate="2016-10-25 23:52:13 +0000"}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-10-25 23:52:13 +0000, expired = YES

After killing

We deleted everything, but the javascript claims that consented = true. Although it doesn't seem to get to the native code.

Oct 25 19:14:22 ucb-sdb-iphone-4 emission[1704] <Warning>: DEBUG:required consent version = {"protocol_id":"2014-04-6267","approval_date":"2016-07-14"}
Oct 25 19:14:22 ucb-sdb-iphone-4 emission[1704] <Warning>: DEBUG: required consent version = {"protocol_id":"2014-04-6267","approval_date":"2016-07-14"}
Oct 25 19:14:22 ucb-sdb-iphone-4 emission[1704] <Warning>: THREAD WARNING: ['UnifiedLogger'] took '14.770020' ms. Plugin should use a background thread.
Oct 25 19:14:22 ucb-sdb-iphone-4 emission[1704] <Warning>: Consented, no need to show consent

The native code does detect that consented = NO

Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: BEMDataCollection:pluginInitialize singleton -> initialize statemachine and delegate
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: no cloud sync at path: /var/mobile/Containers/Data/Application/FD9D523C-7355-4BD6-BF4F-005D22809565/Library/LocalDatabase
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: reqConsent = 2016-07-14, currConfig.approval_date = (null)
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: no cloud sync at path: /var/mobile/Containers/Data/Application/FD9D523C-7355-4BD6-BF4F-005D22809565/Library/LocalDatabase
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: DEBUG: reqConsent = 2016-07-14, currConfig.approval_date = (null)
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: isConsented = NO
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: DEBUG: isConsented = NO
Oct 25 19:17:33 ucb-sdb-iphone-4 emission[1709] <Warning>: [CDVTimer][datacollection] 30.916989ms

Then, currAuth is null, so we re-read it and it is expired.

Oct 25 19:14:23 ucb-sdb-iphone-4 emission[1704] <Warning>: currAuth = null, reading the current value from the keychain
Oct 25 19:14:23 ucb-sdb-iphone-4 emission[1704] <Warning>: DEBUG: currAuth = null, reading the current value from the keychain
Oct 25 19:14:23 ucb-sdb-iphone-4 emission[1704] <Warning>: currAuth = GTMOAuth2Authentication 0x157826ce0: {refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES

And we can't refresh because we can't determine the client ID

Oct 25 19:14:23 ucb-sdb-iphone-4 emission[1704] <Warning>: Error Error Domain=com.google.HTTPStatus Code=400 "(null)" UserInfo={data=<7b0a2022 6572726f 72223a20 22696e76 616c6964 5f726571 75657374 222c0a20 22657272 6f725f64 65736372 69707469 6f6e223a 2022436f 756c6420 6e6f7420 64657465 726d696e 6520636c 69656e74 20494420 66726f6d 20726571 75657374 2e222c0a 20226572 726f725f 75726922 3a202222 0a7d0a>}
    Error data:
    {
        error = "invalid_request";
        "error_description" = "Could not determine client ID from request.";
        "error_uri" = "";
    }

Then, we try a sync

Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: backgroundSync called
Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: INFO: backgroundSync called
Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: pushAndClearUserCache called
Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: DEBUG: pushAndClearUserCache called

We call sth in CommunicationHelper 

Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: CommunicationHelper.execute called!
Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: currAuth != null, nothing to do
Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: currAuth = GTMOAuth2Authentication 0x15012a360: {refreshToken="1/eGsjKoDgjalhb_2W4cqTJImlN0x7PfOm425VmXFpfk4"}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES

And then refresh magically works.

Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: Refresh completion block called, refreshed token expires at 2016-10-26 03:17:43 +0000
Oct 25 19:17:43 ucb-sdb-iphone-4 emission[1709] <Warning>: Refresh is really done, returning refreshed token

Ok, so the answer is that the CommunicationHelper code path appears to set the clientId and clientSecret independently.

Aha! It is here. This is the only other use of getGoogleiOSClientID in the code.

- (void)pluginInitialize
{
    // Handle google+ sign on
    [AuthCompletionHandler sharedInstance].clientId = [[ConnectionSettings sharedInstance] getGoogleiOSClientID];
    [AuthCompletionHandler sharedInstance].clientSecret = [[ConnectionSettings sharedInstance] getGoogleiOSClientSecret];
}
shankari commented 7 years ago

So we do use the native JWT auth code for all calls, so why didn't the non-sync path use this. Aha! Because the values are set in the pluginInitialize. And that is not called onLoad. But the plugin is loaded when we navigate to the control screen to clear and sync.

I'm going to leave this running while I have dinner and confirm that the force sync also fails if not triggered manually.

shankari commented 7 years ago

Confirmed!

Cleared all entries and killed the app.

Oct 25 21:43:59 ucb-sdb-iphone-4 emission[1720] <Warning>: THREAD WARNING: ['UserCache'] took '29.039062' ms. Plugin should use a background thread.
Oct 25 21:44:05 ucb-sdb-iphone-4 com.apple.xpc.launchd[1] (UIKitApplication:edu.berkeley.eecs.emission[0xb000][1720]) <Notice>: Service exited due to signal: Killed: 9

After that, we were woken up for every push, but then killed. There's probably a crash somewhere in the code when we can't auth for the background sync.

Oct 25 21:55:42 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Oct 25 22:00:14 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Oct 25 22:00:14 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed

Oct 25 22:10:42 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed
Oct 25 22:24:18 ucb-sdb-iphone-4 UserEventAgent[26] <Warning>: processing edu.berkeley.eecs.emission with 6 events
Oct 25 22:25:42 ucb-sdb-iphone-4 SpringBoard[58] <Warning>: High Priority Push: edu.berkeley.eecs.emission - App killed

No further crashes. I guess app was killed due to lack of progress or sth. Should probably improve error handling of the remote push to avoid that.

shankari commented 7 years ago

So there are two fixes:

shankari commented 7 years ago

Split the clear of the entries and the documents so that we can do one on push and the other on pull

we need to figure out what to do about RW documents. I propose that, for now, the last RW document should always be retained. This is particularly important for things like consent because the default is not consented.

All our RW documents currently represent user inputs, echoed back, so this will ensure that we never lose user configurations. We need to figure out a solution for server side overrides, but this is not the time for it. And those could be views with a different key anyway (e.g. config/user_sensor_config and config/server_sensor_config) or something like that.

shankari commented 7 years ago

Ensure that we init the jwt auth code even if consent is turned off

This fix (https://github.com/shankari/cordova-jwt-auth/commit/2185c348215c5a014bf609ad7f7f675af78cc720) seems to have broken regular background auth in the case in which we do have consent. And the auth is broken even when the UI is launched. Force killing the app and restarting fixes it, but that is a shitty solution.

Log showing this behavior. loggerDB.auth_error_second_time.withdate.log.gz

shankari commented 7 years ago

First error is here

16930,1478545211.13,2016-11-07 11:00:11.125030-07:53,"Error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={
    error = ""invalid_request"";
    ""error_description"" = ""Could not determine client ID from request."";

Just before that, we started a sync and detected that the token needed to be refreshed.

16895,1478545205.75,2016-11-07 11:00:05.745250-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
16897,1478545205.81,2016-11-07 11:00:05.809420-07:53,"currAuth = GTMOAuth2Authentication 0x147534330: {refreshToken=""1/NPPtNsyNgZIoHOreDUlADYdgyxfGhC5_oxhhWWI0ZlA""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
16900,1478545205.86,2016-11-07 11:00:05.858270-07:53,"In TripDiaryStateMachine, received transition T_RECEIVED_SILENT_PUSH in state STATE_WAITING_FOR_TRIP_START"

And just before that, we had successfully launched a sync, along with a valid token.

16843,1478544691.45,2016-11-07 10:51:31.451990-07:53,Moved from STATE_ONGOING_TRIP to STATE_WAITING_FOR_TRIP_START
16844,1478544691.47,2016-11-07 10:51:31.469510-07:53,backgroundSync called
16845,1478544691.51,2016-11-07 10:51:31.507090-07:53,pushAndClearUserCache called
16846,1478544691.71,2016-11-07 10:51:31.711790-07:53,pullIntoUserCache called

As part of that, we refreshed the token.

16847,1478544691.76,2016-11-07 10:51:31.763320-07:53,about to launch remote call for server_to_phone
16848,1478544691.78,2016-11-07 10:51:31.782340-07:53,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
16851,1478544691.87,2016-11-07 10:51:31.869460-07:53,"currAuth = GTMOAuth2Authentication 0x12fd9e7b0: {accessToken=""ya29.CjCPA6YaM4dj4iRy0D__ZWwJmFz3z17g34q7FQh-w6oBL0tpn1apdSiuNmVixC72Ul0"", refreshToken=""1/NPPtNsyNgZIoHOreDUlADYdgyxfGhC5_oxhhWWI0ZlA"", expirationDate=""2016-11-07 18:00:29 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-11-07 18:00:29 +0000, expired = YES"
16862,1478544693.03,2016-11-07 10:51:33.031790-07:53,"Refresh completion block called, refreshed token expires at 2016-11-07 19:51:33 +0000"

And then we read the docs.

16871,1478544766.21,2016-11-07 10:52:46.214780-07:53,received response for server_to_phone
16883,1478544766.91,2016-11-07 10:52:46.910700-07:53,Retrieved 10 documents

And then nothing until the next background sync started (the one that failed) started.

16883,1478544766.91,2016-11-07 10:52:46.910700-07:53,Retrieved 10 documents 16884,1478545204.88,2016-11-07 11:00:04.876410-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"

As we can see from previous successful runs, we expected to print the document keys and then send a DATA_PUSHED transition after the retrieval, but that never happened.

16381,1478539806.41,2016-11-07 09:30:06.409170-07:53,Retrieved 10 documents
16382,1478539806.45,2016-11-07 09:30:06.449880-07:53,"After clear complete, cache has entries stats/client_time, statemachine/transition, background/battery, stats/client_nav_event, config/sync_config, config/sensor_config, config/consent, diary/trips-2016-10-31, diary/trips-2016-11-01, diary/trips-2016-11-02, diary/trips-2016-11-05, diary/trips-2016-11-04, diary/trips-2016-11-07, common-trips"
16383,1478539806.47,2016-11-07 09:30:06.466380-07:53,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
16384,1478539806.53,2016-11-07 09:30:06.525470-07:53,Received notification T_DATA_PUSHED while processing silent push notification
16385,1478539806.54,2016-11-07 09:30:06.544090-07:53,"Data pushed, fetch result = new data"

So presumably, the app was terminated because it was running too long? So then get/put took more than a minute! Need to see why this is happening, and whether we should do something of scalability on the server. Also, we should change iPhone1 to have a 50m distance filter...

16819,1478544690.18,2016-11-07 10:51:30.181940-07:53,"Received visit notification = <+37.40387492,-122.08363315> +/- 31.26m (2016-11-07 18:46:29 +0000 to -)"
16826,1478544690.38,2016-11-07 10:51:30.376110-07:53,"In TripDiaryStateMachine, received transition T_TRIP_END_DETECTED in state STATE_ONGOING_TRIP"
16867,1478544693.13,2016-11-07 10:51:33.131740-07:53,postToHost called with url = /usercache/get -- https://e-mission.eecs.berkeley.edu
16870,1478544693.19,2016-11-07 10:51:33.186350-07:53,postToHost called with url = /usercache/put -- https://e-mission.eecs.berkeley.edu
16871,1478544766.21,2016-11-07 10:52:46.214780-07:53,received response for server_to_phone

So when the app is again restarted to handle the push notification, the currAuth is null, so we try to recreate it. But because it is not a UI launch, we don't initialize the plugin, so the clientID is not set, and the refresh fails.

Ok, so then when we do launch the client, why does the plugin not get loaded and initialize the value?

Oh wait, the plugins are initialized, it is just that the JWT auth plugin is initialized AFTER the token refresh. Note that we pre-emptively launch the token refresh when we get a background sync so that they can be ready for any push/pull.

Refresh launched and then plugins initialized.

16885,1478545204.89,2016-11-07 11:00:04.891850-07:53,"currAuth = null, reading the current value from the keychain"
16886,1478545204.92,2016-11-07 11:00:04.916600-07:53,"currAuth = GTMOAuth2Authentication 0x147534330: {refreshToken=""1/NPPtNsyNgZIoHOreDUlADYdgyxfGhC5_oxhhWWI0ZlA""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
16887,1478545204.93,2016-11-07 11:00:04.933590-07:53,"token has expired, refreshing it"
16888,1478545204.95,2016-11-07 11:00:04.952530-07:53,beginning refresh of token expiring at (null)
16889,1478545205.27,2016-11-07 11:00:05.272670-07:53,finished init of iOS native code
16890,1478545205.29,2016-11-07 11:00:05.290800-07:53,truncating obsolete entries before 1475953205.289777
16891,1478545205.37,2016-11-07 11:00:05.372570-07:53,"reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14"
16892,1478545205.39,2016-11-07 11:00:05.388600-07:53,isConsented = YES

Unfortunately, I don't log the JWT Auth init and when I set the clientID and clientSecret.

34005,1478795595.71,2016-11-10 08:33:15.713820-07:53,Application is about to terminate
34006,1478795595.74,2016-11-10 08:33:15.735320-07:53,onAppTerminate called

The auth is != null, so we don't do anything about it.

33904,1478793605.67,2016-11-10 08:00:05.666570-07:53,About to set theme from preference
33905,1478793605.69,2016-11-10 08:00:05.685260-07:53,preferred theme = null
33906,1478793605.7,2016-11-10 08:00:05.701720-07:53,set dark_theme = false
33907,1478793605.74,2016-11-10 08:00:05.737170-07:53,About to navigate to preferred tab
33908,1478793605.75,2016-11-10 08:00:05.754070-07:53,changing state to root.main.metrics
33911,1478793608.07,2016-11-10 08:00:08.073780-07:53,CommunicationHelper.execute called!
33912,1478793608.09,2016-11-10 08:00:08.086580-07:53,"currAuth != null, nothing to do"
33913,1478793608.1,2016-11-10 08:00:08.104480-07:53,"currAuth = GTMOAuth2Authentication 0x155d558f0: {refreshToken=""1/NPPtNsyNgZIoHOreDUlADYdgyxfGhC5_oxhhWWI0ZlA""}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES"
33914,1478793608.12,2016-11-10 08:00:08.119450-07:53,"token has expired, refreshing it"
33915,1478793608.14,2016-11-10 08:00:08.138040-07:53,beginning refresh of token expiring at (null)
33916,1478793608.16,2016-11-10 08:00:08.160070-07:53,"Error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={

I would assume that although currAuth != NULL, we can still set the clientID and secret after it has been created, since the code looks like this.

- (void)pluginInitialize
{
    // Handle google+ sign on
    [AuthCompletionHandler sharedInstance].clientId = [[ConnectionSettings sharedInstance] getGoogleiOSClientID];
    [AuthCompletionHandler sharedInstance].clientSecret = [[ConnectionSettings sharedInstance] getGoogleiOSClientSecret];
}

I guess it could be that the sharedInstance method, which does not use dispatch_once (unlike TripDiaryStateMachine::instance`) might be creating multiple entries for the instance.

shankari commented 7 years ago

Note also that because we deleted all documents, and then were terminated before we could save the newly retrieved documents, we lost consent. That is probably the reason why we were losing consent earlier as well. This is not an issue for an installs after https://github.com/shankari/cordova-usercache/commit/f35f39a1766ee660519a7481eb05c8ac7d8be43b, but is an issue for prior installs because the rw-document has been replaced by a document, which could be deleted.

16892,1478545205.39,2016-11-07 11:00:05.388600-07:53,isConsented = YES
    ""error_description"" = ""Could not determine client ID from request."";
....
    ""error_description"" = ""Could not determine client ID from request."";
33825,1478786409.32,2016-11-10 06:00:09.321140-07:53,isConsented = NO
33829,1478786409.79,2016-11-10 06:00:09.791970-07:53,isConsented = NO
33836,1478786410.16,2016-11-10 06:00:10.155210-07:53,isConsented = NO
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
33847,1478788204.73,2016-11-10 06:30:04.734350-07:53,isConsented = NO
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
33856,1478790004.41,2016-11-10 07:00:04.409140-07:53,isConsented = NO
33863,1478790004.67,2016-11-10 07:00:04.669790-07:53,isConsented = NO
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
33874,1478791804.15,2016-11-10 07:30:04.149030-07:53,isConsented = NO
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
33883,1478793603.54,2016-11-10 08:00:03.542880-07:53,isConsented = NO
33890,1478793603.73,2016-11-10 08:00:03.732530-07:53,isConsented = NO
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
    ""error_description"" = ""Could not determine client ID from request."";
34010,1478795600.78,2016-11-10 08:33:20.783460-07:53,isConsented = YES
...
shankari commented 7 years ago

This happened again after I fixed it the first time. This time:

35268,1478851225.57,2016-11-11 00:00:25.574650-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
35270,1478851225.63,2016-11-11 00:00:25.629570-07:53,"currAuth = GTMOAuth2Authentication 0x136f2eb00: {accessToken=""ya29.CjCTA2U1zcNvnoGa29WRxG-BOly14ZKrW5c3J4KzePba-S2Dq1WgOfcjjD8YPOW_sio"", refreshToken=""1/Dh8lijsDL5-NBD4Bc97t-t_QCgWghm0CoRgO1CawBO4D-3LcVlEj5z5PzJkRkYUi"", expirationDate=""2016-11-11 08:00:06 +0000""}, canAuthorize = YES, expiresIn = 3600, expirationDate = 2016-11-11 08:00:06 +0000, expired = YES"
35271,1478851225.65,2016-11-11 00:00:25.647340-07:53,"token has expired, refreshing it"
35272,1478851225.67,2016-11-11 00:00:25.665710-07:53,beginning refresh of token expiring at 2016-11-11 08:00:06 +0000
35278,1478851225.84,2016-11-11 00:00:25.838750-07:53,pullIntoUserCache called
35279,1478851225.87,2016-11-11 00:00:25.874800-07:53,about to launch remote call for server_to_phone
35280,1478851225.89,2016-11-11 00:00:25.889700-07:53,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
35289,1478851226.08,2016-11-11 00:00:26.081410-07:53,isConsented = YES

Sync completed on the first thread

35336,1478852047.84,2016-11-11 00:14:07.835650-07:53,Retrieved 10 documents
35337,1478852047.88,2016-11-11 00:14:07.875680-07:53,"After clear complete, cache has entries config/consent, background/battery, stats/client_time, statemachine/transition, stats/client_nav_event, config/sensor_config, config/sync_config, diary/trips-2016-11-09, diary/trips-2016-11-08, diary/trips-2016-11-10, diary/trips-2016-11-05, diary/trips-2016-11-04, diary/trips-2016-11-07, common-trips"
35338,1478852047.89,2016-11-11 00:14:07.892630-07:53,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
35339,1478852047.95,2016-11-11 00:14:07.950330-07:53,Received notification T_DATA_PUSHED while processing silent push notification
35340,1478852047.97,2016-11-11 00:14:07.965630-07:53,"Data pushed, fetch result = new data"

Sync completed on the second thread 

35353,1478852048.88,2016-11-11 00:14:08.876160-07:53,Retrieved 10 documents
35354,1478852048.92,2016-11-11 00:14:08.917430-07:53,"After clear complete, cache has entries config/consent, background/battery, stats/client_time, statemachine/transition, stats/client_nav_event, config/sensor_config, config/sync_config, diary/trips-2016-11-09, diary/trips-2016-11-08, diary/trips-2016-11-10, diary/trips-2016-11-05, diary/trips-2016-11-04, diary/trips-2016-11-07, common-trips"
35355,1478852048.94,2016-11-11 00:14:08.936100-07:53,"In TripDiaryStateMachine, received transition T_DATA_PUSHED in state STATE_WAITING_FOR_TRIP_START"
35356,1478852048.99,2016-11-11 00:14:08.991440-07:53,Received notification T_DATA_PUSHED while processing silent push notification
35357,1478852049.01,2016-11-11 00:14:09.008150-07:53,"Data pushed, fetch result = new data"

Next sync starts, but currAuth == null. Note that since the sync completed this time, we have consent and the other plugin initializations happen after the currAuth check.

35358,1478854805.91,2016-11-11 01:00:05.912150-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
35359,1478854805.93,2016-11-11 01:00:05.931120-07:53,"currAuth = null, reading the current value from the keychain"
35364,1478854806.03,2016-11-11 01:00:06.034290-07:53,isConsented = YES
35365,1478854806.44,2016-11-11 01:00:06.435370-07:53,finished init of iOS native code
shankari commented 7 years ago

Ok, the theory in https://github.com/e-mission/cordova-jwt-auth/issues/8#issuecomment-260213092 is borne out

First break 

0,1478174925.22,2016-11-03 05:08:45.219720-07:53,finished init of iOS native code

8,1478281218.79,2016-11-04 10:40:18.793750-07:53,finished init of iOS native code

2566,1478347205.13,2016-11-05 05:00:05.128510-07:53,"currAuth = null, reading the current value from the keychain"
2570,1478347205.55,2016-11-05 05:00:05.545010-07:53,finished init of iOS native code
2607,1478347208.12,2016-11-05 05:00:08.118130-07:53,"Error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={
2608,1478347208.14,2016-11-05 05:00:08.141000-07:53,"Error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={

Second break

19603,1478646015.56,2016-11-08 15:00:15.561270-07:53,"Got error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={

19614,1478647135.98,2016-11-08 15:18:55.977590-07:53,finished init of iOS native code
19637,1478647140.06,2016-11-08 15:19:00.057590-07:53,"currAuth = null, reading the current value from the keychain"

19735,1478650560.37,2016-11-08 16:16:00.369660-07:53,finished init of iOS native code
19765,1478650571.75,2016-11-08 16:16:11.747780-07:53,"currAuth = null, reading the current value from the keychain"

24806,1478715480.91,2016-11-09 10:18:00.908570-07:53,finished init of iOS native code
24825,1478715484.66,2016-11-09 10:18:04.662860-07:53,"currAuth = null, reading the current value from the keychain"

24835,1478715575.38,2016-11-09 10:19:35.377000-07:53,finished init of iOS native code
24858,1478715579.04,2016-11-09 10:19:39.040510-07:53,"currAuth = null, reading the current value from the keychain"

24870,1478719676.22,2016-11-09 11:27:56.216240-07:53,finished init of iOS native code
24905,1478719683.73,2016-11-09 11:28:03.730100-07:53,"currAuth = null, reading the current value from the keychain"

25871,1478727359.17,2016-11-09 13:35:59.166680-07:53,finished init of iOS native code
25895,1478727363.06,2016-11-09 13:36:03.062170-07:53,"currAuth = null, reading the current value from the keychain"

26985,1478736081.37,2016-11-09 16:01:21.366790-07:53,finished init of iOS native code
27009,1478736086.85,2016-11-09 16:01:26.851700-07:53,"currAuth = null, reading the current value from the keychain"

35359,1478854805.93,2016-11-11 01:00:05.931120-07:53,"currAuth = null, reading the current value from the keychain"
35365,1478854806.44,2016-11-11 01:00:06.435370-07:53,finished init of iOS native code
35406,1478854809.15,2016-11-11 01:00:09.146560-07:53,"Error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={
35407,1478854809.17,2016-11-11 01:00:09.165230-07:53,"Error Error Domain=com.google.HTTPStatus Code=400 ""(null)"" UserInfo={json={
shankari commented 7 years ago

So I think that we need two fixes:

shankari commented 7 years ago

Ran into the data collection error even after this fix. Details.

Sync started, consent is true. Sync does not complete (probably due to network errors).

112625,1479153626.24,2016-11-14 12:00:26.235520-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
112628,1479153626.29,2016-11-14 12:00:26.291090-07:53,"token has expired, refreshing it"
112629,1479153626.34,2016-11-14 12:00:26.343790-07:53,beginning refresh of token expiring at (null)
112634,1479153626.72,2016-11-14 12:00:26.719070-07:53,about to launch remote call for server_to_phone
112635,1479153626.74,2016-11-14 12:00:26.740750-07:53,About to check rw state for config config/consent
112636,1479153626.77,2016-11-14 12:00:26.765270-07:53,"Already have rw-document for key config/consent, nothing to fix"
112641,1479153626.88,2016-11-14 12:00:26.876180-07:53,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
112649,1479153627.06,2016-11-14 12:00:27.062120-07:53,"reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14"
112650,1479153627.08,2016-11-14 12:00:27.080940-07:53,isConsented = YES

Sync started, consent is true. Sync does not complete (probably due to network errors).

112656,1479155410.14,2016-11-14 12:30:10.139750-07:53,"Received background sync call when useRemotePush = 1, about to check whether a trip has ended"
112659,1479155410.2,2016-11-14 12:30:10.202000-07:53,"token has expired, refreshing it"
112660,1479155410.24,2016-11-14 12:30:10.235140-07:53,beginning refresh of token expiring at (null)
112665,1479155410.61,2016-11-14 12:30:10.606320-07:53,about to launch remote call for server_to_phone
112666,1479155410.62,2016-11-14 12:30:10.622160-07:53,About to check rw state for config config/consent
112667,1479155410.65,2016-11-14 12:30:10.646600-07:53,"Already have rw-document for key config/consent, nothing to fix"
112672,1479155410.94,2016-11-14 12:30:10.938110-07:53,deleteDocQuery = DELETE FROM userCache WHERE type = 'document'
112680,1479155411.15,2016-11-14 12:30:11.153630-07:53,"reqConsent = 2016-07-14, currConfig.approval_date = 2016-07-14"
112681,1479155411.17,2016-11-14 12:30:11.173390-07:53,isConsented = YES
112682,1479155411.21,2016-11-14 12:30:11.206080-07:53,"Error Error Domain=NSURLErrorDomain Code=-1001 ""The request timed out."" UserInfo={NSUnderlyingError=0x147ed4c60 {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"
112689,1479155411.35,2016-11-14 12:30:11.348320-07:53,"After clear complete, cache has entries config/sync_config, stats/client_time, statemachine/transition, background/battery, stats/client_nav_event, config/consent, config/sensor_config, background/location, background/filtered_location"

Sync started, consent is true. Sync completes and deletes rw-documents that were before the min(time_period_end, last document_write_ts). So if the last document was inserted in this time period, min(time_period_end, last_document_write_ts) = last_document_write_ts and we delete all rw-documents whose write_ts is <, not <= the current one.

Let's add some more logging...

112748,1479155435.8,2016-11-14 12:30:35.796860-07:53,Clearing entries for timequery 1479141009.267402 -> 1479155411.328353
112749,1479155435.81,2016-11-14 12:30:35.811840-07:53,deleteQuery = DELETE FROM userCache WHERE (write_ts > 1479141009.267402 AND write_ts < 1479155411.328353 AND type != 'rw-document' AND type != 'document')
112752,1479155435.9,2016-11-14 12:30:35.904950-07:53,"rwDocDeleteQuery = DELETE FROM userCache WHERE type = 'rw-document' AND write_ts < MIN(1479155411, (SELECT MAX(write_ts) FROM userCache WHERE (key = 'config/consent' AND type = 'rw-document')))"
112754,1479155436.0,2016-11-14 12:30:35.996850-07:53,"After clear complete, cache has entries config/sensor_config, statemachine/transition, background/battery, background/location, background/filtered_location, stats/client_time"
shankari commented 7 years ago

Logging showed that this was because of not looking at the key while deleting. https://github.com/e-mission/cordova-usercache/issues/24#issuecomment-261474390

Should be finally fixed by https://github.com/e-mission/cordova-usercache/issues/24