search

couchbase / couchbase-lite-ios

Lightweight, embedded, syncable NoSQL database engine for iOS and MacOS apps.
Apache License 2.0
1.63k stars 297 forks source link

pull isn't run automatically after saveAllowingConflict called #617

Closed danilNil closed 9 years ago

danilNil commented 9 years ago

Hello,

I've created sample app: https://github.com/danilNil/cbl-simple-sync I'm trying to understand how to work with merging conflicts. I've found that I need to call 

for (CBLReplication * repl in @[push, pull]) {
    [repl start];
}

manually after I've resolved conflicts because it doesn't handle saveAllowingConflict call.

environment: (macos, walrus, pod 'couchbase-lite-ios', '~> 1.0.3', [repl setContinuous:YES];)

Here is my steps:

1) open app on device and simulator 2) put some text inside fields on simulator 3) click 'update' button on simulator 4) click 'refresh' button on device 5) sync is works 6) turn off network on device 7) update fields on simulator click update button to save them 8) update fields on device click update button to save them 9) turn on network on device 10) click 'refresh' 11) click 'check conflicts' 12) fields become updated correctly. saveAllowingConflict called for correct revision 13) click 'refresh' on simulator to fetch updates from data base and apply them in UI. Nothing changed. 14) Rerun app on device 15) click 'refresh' on simulator to fetch updates from data base and apply them in UI. got it. or 14) call [repl start]; 15) click 'refresh' on simulator to fetch updates from data base and apply them in UI. got it.

Please let me know if I miss something. Thanks!

UPDATE: seems like continuous replication is no more working after I merged conflicts. I didn't get any updates from sync gateway. I've checked out that they are there by curl: curl http://192.168.0.100:4984/gw/123

snej commented 9 years ago

Sounds like the replications don't re-activate after you turn the network back on (which would be a bug.) Try observing the replications with NSNotificationCenter to see when their status changes and log the results.

pasin commented 9 years ago

Could you disable your runSync workaround in ViewController.m and rerun with Sync and SyncVerbose log enabled as below? It would be more clear about what was going on with the log.

[CBLManager enableLogging:@"Sync"];
[CBLManager enableLogging:@"SyncVerbose"];
pasin commented 9 years ago

@danilNil I went to test your app (I removed your runSync workaround) but I couldn't reproduce the same issue that you have. However, there is one thing related to the iOS reachability that I found while testing.

For step 6 and 9, if I turned the airplane mode off and on while the app was still on the foreground, I got some delay from the pull replication as the reachability reported the status twice, one for an intermediate 3G connection and the other one for the WiFi connection.

When the puller received the first reachable via 3G connection, the puller went online and tried to connect with that 3G connection which resulted to a connection timeout delay. The second reachable via WiFi was ignored due to the puller already went online. The puller resumed its duty correctly after the timeout delay. Here is the reachability logs:

2015-03-03 21:27:30.018 cbl-simple-sync[488:96649] Sync: CBL_Pusher[http://10.0.1.7:4984/gw]: Reachability state = <10.0.1.7>:unreachable (40007), suspended=0
2015-03-03 21:27:30.019 cbl-simple-sync[488:96649] Sync: CBL_Puller[http://10.0.1.7:4984/gw]: Reachability state = <10.0.1.7>:unreachable (40007), suspended=0
2015-03-03 21:27:31.497 cbl-simple-sync[488:96649] Sync: CBL_Puller[http://10.0.1.7:4984/gw]: Reachability state = <10.0.1.7>:reachable (3G) (40003), suspended=0
2015-03-03 21:27:31.498 cbl-simple-sync[488:96649] Sync: CBL_Puller[http://10.0.1.7:4984/gw]: Going online
2015-03-03 21:27:31.498 cbl-simple-sync[488:96649] Sync: CBL_Puller[http://10.0.1.7:4984/gw] Progress: set active = 1
2015-03-03 21:27:31.498 cbl-simple-sync[488:96649] SyncVerbose: CBL_Puller[http://10.0.1.7:4984/gw]: postProgressChanged (1/1, active=1 (batch=0, net=1), online=1)
2015-03-03 21:27:31.498 cbl-simple-sync[488:96649] SyncVerbose: CBL_Puller[http://10.0.1.7:4984/gw]: GET _local/12180da5047261e951ded69d431e3296216196f2
2015-03-03 21:27:31.499 cbl-simple-sync[488:96649] SyncVerbose: CBL_Puller[http://10.0.1.7:4984/gw]: postProgressChanged (1/1, active=1 (batch=0, net=1), online=1)
2015-03-03 21:27:31.499 cbl-simple-sync[488:96599] Sync: CBLReplication[from http://10.0.1.7:4984/gw]: active, progress = 1 / 1, err: (null)
2015-03-03 21:27:31.499 cbl-simple-sync[488:96649] Sync: CBL_Pusher[http://10.0.1.7:4984/gw]: Reachability state = <10.0.1.7>:reachable (3G) (40003), suspended=0
2015-03-03 21:27:31.508 cbl-simple-sync[488:96649] Sync: CBL_Pusher[http://10.0.1.7:4984/gw]: Going online
2015-03-03 21:27:31.514 cbl-simple-sync[488:96649] Sync: CBL_Pusher[http://10.0.1.7:4984/gw] Progress: set active = 1
2015-03-03 21:27:31.514 cbl-simple-sync[488:96649] SyncVerbose: CBL_Pusher[http://10.0.1.7:4984/gw]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-03-03 21:27:31.514 cbl-simple-sync[488:96649] SyncVerbose: CBL_Pusher[http://10.0.1.7:4984/gw]: GET _local/9a92a99e0c1198d72c2d4a95a251b4e06a351902
2015-03-03 21:27:31.514 cbl-simple-sync[488:96649] SyncVerbose: CBL_Pusher[http://10.0.1.7:4984/gw]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
2015-03-03 21:27:31.515 cbl-simple-sync[488:96599] Sync: CBLReplication[to http://10.0.1.7:4984/gw]: active, progress = 0 / 0, err: (null)
2015-03-03 21:27:31.627 cbl-simple-sync[488:96649] Sync: CBL_Pusher[http://10.0.1.7:4984/gw]: Reachability state = <10.0.1.7>:reachable (20002), suspended=0
2015-03-03 21:27:31.634 cbl-simple-sync[488:96649] Sync: CBL_Puller[http://10.0.1.7:4984/gw]: Reachability state = <10.0.1.7>:reachable (20002), suspended=0
2015-03-03 21:27:33.429 cbl-simple-sync[488:96599] personQuery run:&error: (null)
2015-03-03 21:28:32.005 cbl-simple-sync[488:96649] CBLRemoteJSONRequest[GET http://10.0.1.7:4984/gw/_local/12180da5047261e951ded69d431e3296216196f2]: Got error Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo=0x1700e4f00 {NSUnderlyingError=0x174052a50 "The request timed out.", NSErrorFailingURLStringKey=http://10.0.1.7:4984/gw/_local/12180da5047261e951ded69d431e3296216196f2, NSErrorFailingURLKey=http://10.0.1.7:4984/gw/_local/12180da5047261e951ded69d431e3296216196f2, NSLocalizedDescription=The request timed out.}
2015-03-03 21:28:32.008 cbl-simple-sync[488:96649] CBLRemoteJSONRequest[GET http://10.0.1.7:4984/gw/_local/9a92a99e0c1198d72c2d4a95a251b4e06a351902]: Got error Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo=0x1740e7a00 {NSUnderlyingError=0x174052b10 "The request timed out.", NSErrorFailingURLStringKey=http://10.0.1.7:4984/gw/_local/9a92a99e0c1198d72c2d4a95a251b4e06a351902, NSErrorFailingURLKey=http://10.0.1.7:4984/gw/_local/9a92a99e0c1198d72c2d4a95a251b4e06a351902, NSLocalizedDescription=The request timed out.}

After testing and reading SCNetworkReachability doc, I think the reachability behavior was correct as the iPhone did enabled 3G first and WiFi in about a second or less after. The reachability status was already correct based on the host reachability definition in the document.

\ Update : Based on my testing the delay between reporting 3G (LTE) and reporting WiFi is wary between 100ms to 500ms. I believe the delay could be more or less depending on how fast the device could connect to a cellular network and WiFi network. Not sure if it's worth to try to mitigate the effect of this issue, e.g. by delaying the replicator to goOnline by some milliseconds.

After all, I'm not quite sure why the conflict resolution docs didn't show up on the simulator. Can you enable 'Sync' and 'SyncVerbose' as my previous comment and post your log? Please remove your workaround before running as well.

pasin commented 9 years ago

@danilNil do you have a chance to rerun the app with log enabled again?

danilNil commented 9 years ago

Sorry, guys. I'm going to do it today

Sent from my iPhone

On 7 ìàðòà 2015 ã., at 0:31, Pasin Suriyentrakorn notifications@github.com wrote:

@danilNil do you have a chance to rerun the app with log enabled again?

— Reply to this email directly or view it on GitHub.

danilNil commented 9 years ago

@pasin here is what I found.

1) sync is working 2) turn off wifi on device 3) send update on simulator 4) send update on device 5) turn on wifi on device 6) refresh - ok. we got updates from server 7) check for conflicts - ok

logs:

2015-03-08 20:38:26.909 cbl-simple-sync[1797:1297692] SyncVerbose: CBL_Puller[http://192.168.0.104:4984/gw] finished inserting 1 revisions
2015-03-08 20:38:26.922 cbl-simple-sync[1797:1297692] SyncVerbose: CBL_Puller[http://192.168.0.104:4984/gw]: Setting lastSequence to 129 (from 128)
2015-03-08 20:38:26.925 cbl-simple-sync[1797:1297692] Sync: CBL_Puller[http://192.168.0.104:4984/gw] inserted 1 revs in 0.122 sec (8.2/sec)
2015-03-08 20:38:26.926 cbl-simple-sync[1797:1297692] Sync: CBL_Puller[http://192.168.0.104:4984/gw] Progress: set active = 0
2015-03-08 20:38:26.927 cbl-simple-sync[1797:1297692] SyncVerbose: CBL_Puller[http://192.168.0.104:4984/gw]: postProgressChanged (176/177, active=0 (batch=0, net=0), online=1)
2015-03-08 20:38:26.928 cbl-simple-sync[1797:1297692] Sync: CBL_Puller[http://192.168.0.104:4984/gw] Progress: 177 / 177
2015-03-08 20:38:26.930 cbl-simple-sync[1797:1297692] SyncVerbose: CBL_Puller[http://192.168.0.104:4984/gw]: postProgressChanged (177/177, active=0 (batch=0, net=0), online=1)
2015-03-08 20:38:26.931 cbl-simple-sync[1797:1297641] Sync: CBLReplication[from http://192.168.0.104:4984/gw]: idle, progress = 177 / 177, err: (null)
2015-03-08 20:38:27.239 cbl-simple-sync[1797:1297692] CBLWebSocketChangeTracker[0x17db6ad0 gw]: Connection error #1, retrying in 2.0 sec: The operation couldn’t be completed. Socket is not connected
2015-03-08 20:38:29.246 cbl-simple-sync[1797:1297692] SyncVerbose: CBLWebSocketChangeTracker[0x17db6ad0 gw]: GET //192.168.0.104:4984/gw/_changes?feed=websocket
2015-03-08 20:38:31.930 cbl-simple-sync[1797:1297692] Sync: CBL_Puller[http://192.168.0.104:4984/gw] checkpointing sequence=129
2015-03-08 20:38:31.931 cbl-simple-sync[1797:1297692] SyncVerbose: CBL_Puller[http://192.168.0.104:4984/gw]: PUT _local/4fc71c354f832fc4bada404aacf242b1b6a69967
2015-03-08 20:38:31.986 cbl-simple-sync[1797:1297692] Sync: CBL_Puller[http://192.168.0.104:4984/gw] saved remote checkpoint '129' (_rev=0-7)
2015-03-08 20:38:48.877 cbl-simple-sync[1797:1297641] personQuery run:&error: (null)
2015-03-08 20:38:54.251 cbl-simple-sync[1797:1297641] final properties to merge: {
    "_id" = 123;
    "_rev" = "80-3f9e1eb2d55a1ef40205c6465e84f226";
    name = "1 2 ";
    position = "1 2 ";
}
2015-03-08 20:38:54.252 cbl-simple-sync[1797:1297641] rev prop: {
    "_id" = 123;
    "_rev" = "80-3f9e1eb2d55a1ef40205c6465e84f226";
    name = 1;
    position = 1;
} is deleted: 0
2015-03-08 20:38:54.257 cbl-simple-sync[1797:1297641] rev prop: {
    "_id" = 123;
    "_rev" = "82-c4da05e83c5dc7043cd6ce54a32f695b";
    name = "2 ";
    position = "2 ";
} is deleted: 0
2015-03-08 20:38:54.289 cbl-simple-sync[1797:1297641] personQuery run:&error: (null)

8) refresh fields on simulator - nothing. so I didn't get any updates with merged revisions 9) update field on simulator - I got updates from server on device. revisions conflicted 10) click check conflicts - successfully 11) click refresh on simulator - nothing

you can repeat 9-10 steps again and again and got conflicted revisions on device. So pull is working but push isn't.

in device console I see only CBL_Puller logs but I don't see CBL_Pusher after I merged conflicts at all. I've updated fields on device and save it in data base but again I didn't get any CBL_Puller logs (I was waiting for 10 minutes and nothing changed)

I got something else during testing. If I just turn off/on wifi (3G enabled) and didn't do any updates in offline on my device then everything is ok. Only once I got some errors and push stopped working:

2015-03-08 20:50:29.259 cbl-simple-sync[1819:1303628] Sync: CBL_Puller[http://192.168.0.104:4984/gw] STOPPED
2015-03-08 20:50:29.259 cbl-simple-sync[1819:1303628] Replication: CBL_Puller[http://192.168.0.104:4984/gw] took 120.637 sec; error=Error Domain=CBLHTTP Code=400 "400 bad_request" UserInfo=0x15e8c700 {NSURL=http://192.168.0.104:4984/gw/_local/4fc71c354f832fc4bada404aacf242b1b6a69967, NSLocalizedFailureReason=bad_request, NSLocalizedDescription=400 bad_request}
2015-03-08 20:50:29.263 cbl-simple-sync[1819:1303608] Sync: CBLReplication[from http://192.168.0.104:4984/gw]: stopped, progress = 64 / 64, err: 400 bad_request
2015-03-08 20:50:29.264 cbl-simple-sync[1819:1303628] CBLRemoteJSONRequest[GET http://192.168.0.104:4984/gw/_local/85e3f3cdbc67cd4154b3157e26a0bd72a4e0a536]: Got error Error Domain=CBLHTTP Code=400 "400 bad_request" UserInfo=0x15d7f510 {NSURL=http://192.168.0.104:4984/gw/_local/85e3f3cdbc67cd4154b3157e26a0bd72a4e0a536, NSLocalizedFailureReason=bad_request, NSLocalizedDescription=400 bad_request}
2015-03-08 20:50:29.266 cbl-simple-sync[1819:1303628] Sync: CBL_Pusher[http://192.168.0.104:4984/gw]: Error fetching last sequence: 400 bad_request
2015-03-08 20:50:29.267 cbl-simple-sync[1819:1303628] Sync: CBL_Pusher[http://192.168.0.104:4984/gw] Progress: set error = 400 bad_request
2015-03-08 20:50:29.268 cbl-simple-sync[1819:1303628] Sync: CBL_Pusher[http://192.168.0.104:4984/gw] STOPPING...
2015-03-08 20:50:29.268 cbl-simple-sync[1819:1303628] Sync: Stopping 0 remote requests
2015-03-08 20:50:29.269 cbl-simple-sync[1819:1303628] Sync: CBL_Pusher[http://192.168.0.104:4984/gw] Progress: set active = 0
2015-03-08 20:50:29.269 cbl-simple-sync[1819:1303628] SyncVerbose: CBL_Pusher[http://192.168.0.104:4984/gw]: postProgressChanged (1/1, active=0 (batch=0, net=0), online=1)
2015-03-08 20:50:29.270 cbl-simple-sync[1819:1303628] Sync: CBL_Pusher[http://192.168.0.104:4984/gw] STOPPED
2015-03-08 20:50:29.271 cbl-simple-sync[1819:1303628] Replication: CBL_Pusher[http://192.168.0.104:4984/gw] took 120.878 sec; error=Error Domain=CBLHTTP Code=400 "400 bad_request" UserInfo=0x15d7f510 {NSURL=http://192.168.0.104:4984/gw/_local/85e3f3cdbc67cd4154b3157e26a0bd72a4e0a536, NSLocalizedFailureReason=bad_request, NSLocalizedDescription=400 bad_request}
2015-03-08 20:50:29.273 cbl-simple-sync[1819:1303608] Sync: CBLReplication[to http://192.168.0.104:4984/gw]: stopped, progress = 1 / 1, err: 400 bad_request
2015-03-08 20:50:29.401 cbl-simple-sync[1819:1303608] personQuery run:&error: (null)
2015-03-08 20:50:29.751 cbl-simple-sync[1819:1303628] CBLRemoteJSONRequest[PUT http://192.168.0.104:4984/gw/_local/4fc71c354f832fc4bada404aacf242b1b6a69967]: Got error Error Domain=CBLHTTP Code=405 "405 method not allowed" UserInfo=0x15da9290 {NSURL=http://192.168.0.104:4984/gw/_local/4fc71c354f832fc4bada404aacf242b1b6a69967, NSLocalizedFailureReason=method not allowed, NSLocalizedDescription=405 method not allowed}
2015-03-08 20:50:29.752 cbl-simple-sync[1819:1303628] WARNING: CBL_Puller[http://192.168.0.104:4984/gw]: Unable to save remote checkpoint: Error Domain=CBLHTTP Code=405 "405 method not allowed" UserInfo=0x15da9290 {NSURL=http://192.168.0.104:4984/gw/_local/4fc71c354f832fc4bada404aacf242b1b6a69967, NSLocalizedFailureReason=method not allowed, NSLocalizedDescription=405 method not allowed}
2015-03-08 20:50:39.274 cbl-simple-sync[1819:1303628] Sync: CBL_Pusher[http://192.168.0.104:4984/gw] STOPPING...

So it's not about reachability but about merging conflicts.

*UPDATE

I notice one moment. In my mergeRevisions function I return back same _rev value as I had at first. So I've deleted all fields I'm not responsible for:

[mergedDict removeObjectsForKeys:@[@"_id", @"_rev", @"_revisions"]];

I think it's important but it doesn't fix the issue.

pasin commented 9 years ago

Thanks a lot for your tests and all the logs here. I will look at this in a bit.

pasin commented 9 years ago

Could you made change as follows to your code and see if it works? Basically I'm using userProperties so there is no need to worry about the metadata properties.

Can you also clean up the database (e.g. removing the app on both simulator and device and restarting the sync gateway) before running? 

- (IBAction)checkConflicts:(id)sender {
    CBLDocument* doc = [AppDelegate.database documentWithID: docId];
    NSError* error;
    NSArray* conflicts = [doc getConflictingRevisions: &error];
    if (conflicts.count > 1) {
        // There is more than one current revision, thus a conflict!
        [AppDelegate.database inTransaction: ^BOOL{
            NSDictionary* mergedProps = [self mergeRevisions: conflicts];

            // Delete the conflicting revisions to get rid of the conflict:
            CBLSavedRevision* current = doc.currentRevision;
            for (CBLSavedRevision* rev in conflicts) {
                NSLog(@"rev prop: %@ is deleted: %i", rev.properties, rev.isDeletion);
                CBLUnsavedRevision *newRev = [rev createRevision];
                if (rev == current) {
                    // add the merged revision
                    newRev.userProperties = [NSMutableDictionary dictionaryWithDictionary:mergedProps];
                } else {
                    // mark other conflicts as deleted
                    newRev.isDeletion = YES;
                }

                NSError *error;
                if (![newRev saveAllowingConflict: &error]){
                    NSLog(@"newRev save: &error: %@", error);
                    return NO;
                }
            }
            return YES;
        }];
        [self showCurrentPerson];
    }
}

- (NSDictionary*)mergeRevisions:(NSArray*)conflicts {
    // Note: the first revision in the conflicts array may not be a current revision:
    NSDictionary* userProperties = ((CBLRevision*)conflicts[0]).userProperties;
    NSMutableDictionary* mergedDict = [NSMutableDictionary dictionaryWithDictionary:userProperties];
    for (CBLRevision* rev in conflicts) {
        if (rev == conflicts[0])
            continue;
        for (NSString* key in rev.userProperties) {
            mergedDict[key] = [NSString stringWithFormat:@"%@ %@", mergedDict[key], rev.properties[key]];
        }
    }
    NSLog(@"final properties to merge: %@", mergedDict);
    return mergedDict;
}

Let me now if this helps.

pasin commented 9 years ago

BTW, what is version of the sync gateway you are using?

danilNil commented 9 years ago

Pasin, thanks!

I'm using Couchbase Sync Gateway/1.0.3(81;fa9a6e7) Issue was fixed by using userProperties. So I haven't cleaned databases.

It would be great to update sample code with userProperties: http://developer.couchbase.com/mobile/develop/guides/couchbase-lite/native-api/document/index.html#Understanding%20Conflicts

pasin commented 9 years ago

Glad the hear it solves your issue. I agree that we should fix the code snippet or make it more clear.