CBL marks replication as complete incorrectly

65 views
Skip to first unread message

David Quon

unread,
May 18, 2016, 7:44:03 PM5/18/16
to Couchbase Mobile
We're using CBL version `1.0.4` for iOS using named replication `self.pullReplication.documentIDs
` where were specifying a bunch of documents potentially with attachments.  As an error case after starting the replication `[self.pullReplication start];` we either kill CouchDB or disconnect the Internet from the iPad.  What we were expecting to happen was to get an error from CBL replication to the effect of connectivity was lost.  However CBL seems to keep trying to replicate and eventually gives the same status as a successful replication.  Is this expected behavior?  Is there a way to know if the user got disconnected and the replication didn't complete successfully so the app can inform the user?  Thanks.

Jens Alfke

unread,
May 18, 2016, 8:02:43 PM5/18/16
to mobile-c...@googlegroups.com

> On May 18, 2016, at 4:44 PM, David Quon <dav...@amcoonline.net> wrote:
>
> we either kill CouchDB or disconnect the Internet from the iPad. What we were expecting to happen was to get an error from CBL replication to the effect of connectivity was lost. However CBL seems to keep trying to replicate and eventually gives the same status as a successful replication.

Is this a continuous replication or one-shot?

If the server goes down, the _changes feed request will fail with a socket error. CBL treats this as a transient error and will retry. A one-shot replication will give up after a minute or so. A continuous replication will keep trying in case the server comes back up.

If the device loses its network, the replication will go into the Offline state. IIRC a one-shot will stop, while a continuous replication will wait for the network to come back.

1.0.4 is really old and there have been lots of changes and bug fixes since then, but the above has always been the intended behavior.

—Jens

David Quon

unread,
May 19, 2016, 7:06:04 PM5/19/16
to Couchbase Mobile
> Is this a continuous replication or one-shot? 

It's a one-shot replication.  Is there any way to know that the one-shot replication timed out and gave up?

> If the device loses its network, the replication will go into the Offline state. IIRC a one-shot will stop, while a continuous replication will wait for the network to come back.

Okay so for this case we can just check for `kCBLReplicationOffline`.

> 1.0.4 is really old and there have been lots of changes and bug fixes since then, but the above has always been the intended behavior. 

Yeah we're going to update as soon as we can but we keep having blocking issues in CBL that prohibits us from upgrading.  Hopefully soon as most seem resolved in your next release.  Thanks for your help as always.

Jens Alfke

unread,
May 19, 2016, 7:26:57 PM5/19/16
to mobile-c...@googlegroups.com

On May 19, 2016, at 4:06 PM, David Quon <dav...@amcoonline.net> wrote:

It's a one-shot replication.  Is there any way to know that the one-shot replication timed out and gave up?

Its status changes to Stopped. There should also be a non-nil lastError.

—Jens

David Quon

unread,
May 24, 2016, 6:01:34 PM5/24/16
to Couchbase Mobile
So after investigating this a bit more there were some problems on our side in handling the CBL replication status.  However it seems that CBL is also responding differently that expected above.

For the disconnection of the Internet use case using Airplane Mode:

2016-05-24 11:46:08.089 App[3350:1586061] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 12;
}
2016-05-24 11:46:08.114 App[3350:1585925] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 43;
}
2016-05-24 11:46:08.128 App[3350:1586061] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 72;
}
2016-05-24 11:46:08.139 App[3350:1586061] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 112;
}
2016-05-24 11:46:08.144 App[3350:1586061] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 139;
}
2016-05-24 11:46:09.339 App[3350:1585925] progressInfo = {
    CompletedKey = 12;
    ExpectedKey = 139;
}
2016-05-24 11:46:10.837 App[3350:1585941] progressInfo = {
    CompletedKey = 46;
    ExpectedKey = 139;
}
2016-05-24 11:46:17.710 App[3350:1585941] progressInfo = {
    CompletedKey = 59;
    ExpectedKey = 139;
}
2016-05-24 11:46:20.071 App[3350:1586061] progressInfo = {
    CompletedKey = 60;
    ExpectedKey = 139;
}
2016-05-24 11:46:20.435 App[3350:1586116] WARNING: CBL_Puller[DATABASE]: Unable to save remote checkpoint: Error Domain=NSURLErrorDomain Code=-1009 "The Internet connection appears to be offline." UserInfo={NSErrorFailingURLStringKey=URL_KEY, _kCFStreamErrorCodeKey=8, NSErrorFailingURLKey=URL_KEY, NSLocalizedDescription=The Internet connection appears to be offline., _kCFStreamErrorDomainKey=12, NSUnderlyingError=0x18124e40 {Error Domain=kCFErrorDomainCFNetwork Code=-1009 "The Internet connection appears to be offline." UserInfo={_kCFStreamErrorCodeKey=8, NSErrorFailingURLStringKey=URL_KEY, NSErrorFailingURLKey=URL_KEY, NSLocalizedDescription=The Internet connection appears to be offline., _kCFStreamErrorDomainKey=12}}}


All the above is expected.  However when listening for `kCBLReplicationChangeNotification` notifications we check and both `self.pullReplication.status == kCBLReplicationStopped` and `self.pushReplication.status == kCBLReplicationStopped` was received where we were expecting them to be `kCBLReplicationOffline`.


I'll file the other use case when killing CouchDB as a separate post for clarity.

David Quon

unread,
May 24, 2016, 6:10:59 PM5/24/16
to Couchbase Mobile
For the killing of CouchDB during named replication use case:

2016-05-24 11:40:49.743 App[3344:1584586] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 33;
}
2016-05-24 11:40:49.757 App[3344:1584586] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 63;
}
2016-05-24 11:40:49.868 App[3344:1584584] progressInfo = {
    CompletedKey = 0;
    ExpectedKey = 99;
}
2016-05-24 11:40:50.568 App[3344:1584584] progressInfo = {
    CompletedKey = 8;
    ExpectedKey = 99;
}
2016-05-24 11:40:50.577 App[3344:1584587] progressInfo = {
    CompletedKey = 8;
    ExpectedKey = 139;
}
2016-05-24 11:40:52.299 App[3344:1584586] progressInfo = {
    CompletedKey = 46;
    ExpectedKey = 139;
}
2016-05-24 11:40:53.359 App[3344:1584696] progressInfo = {
    CompletedKey = 47;
    ExpectedKey = 139;
}


#############################
# KILLED COUCHDB HERE
#############################


2016-05-24 11:41:03.944 App[3344:1584584] progressInfo = {
    CompletedKey = 48;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.417 App[3344:1584587] progressInfo = {
    CompletedKey = 50;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.422 App[3344:1584587] progressInfo = {
    CompletedKey = 52;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.450 App[3344:1584561] progressInfo = {
    CompletedKey = 53;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.518 App[3344:1584587] progressInfo = {
    CompletedKey = 55;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.530 App[3344:1584561] progressInfo = {
    CompletedKey = 56;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.573 App[3344:1584561] progressInfo = {
    CompletedKey = 57;
    ExpectedKey = 139;
}
2016-05-24 11:41:04.584 App[3344:1584586] progressInfo = {
    CompletedKey = 59;
    ExpectedKey = 139;
}
2016-05-24 11:41:07.627 App[3344:1584690] WARNING: CBL_Puller[DATABASE]: Unable to save remote checkpoint: Error Domain=NSURLErrorDomain Code=-1004 "Could not connect to the server." UserInfo={NSErrorFailingURLStringKey=URL_KEY, _kCFStreamErrorCodeKey=61, NSErrorFailingURLKey=URL_KEY, NSLocalizedDescription=Could not connect to the server., _kCFStreamErrorDomainKey=1, NSUnderlyingError=0x15ffb8f0 {Error Domain=kCFErrorDomainCFNetwork Code=-1004 "Could not connect to the server." UserInfo={_kCFStreamErrorCodeKey=61, NSErrorFailingURLStringKey=URL_KEY, NSErrorFailingURLKey=URL_KEY, NSLocalizedDescription=Could not connect to the server., _kCFStreamErrorDomainKey=1}}}
2016-05-24 11:41:16.060 App[3344:1584561] progressInfo = {
    CompletedKey = 60;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.590 App[3344:1584713] progressInfo = {
    CompletedKey = 61;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.596 App[3344:1584713] progressInfo = {
    CompletedKey = 62;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.598 App[3344:1584713] progressInfo = {
    CompletedKey = 63;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.650 App[3344:1584587] progressInfo = {
    CompletedKey = 64;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.669 App[3344:1584586] progressInfo = {
    CompletedKey = 65;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.699 App[3344:1584561] progressInfo = {
    CompletedKey = 66;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.730 App[3344:1584713] progressInfo = {
    CompletedKey = 67;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.761 App[3344:1584586] progressInfo = {
    CompletedKey = 68;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.785 App[3344:1584586] progressInfo = {
    CompletedKey = 69;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.799 App[3344:1584586] progressInfo = {
    CompletedKey = 70;
    ExpectedKey = 139;
}
2016-05-24 11:41:16.811 App[3344:1584586] progressInfo = {
    CompletedKey = 71;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.141 App[3344:1584586] progressInfo = {
    CompletedKey = 72;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.719 App[3344:1584545] progressInfo = {
    CompletedKey = 73;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.727 App[3344:1584545] progressInfo = {
    CompletedKey = 75;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.786 App[3344:1584587] progressInfo = {
    CompletedKey = 76;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.789 App[3344:1584586] progressInfo = {
    CompletedKey = 77;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.861 App[3344:1584545] progressInfo = {
    CompletedKey = 78;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.867 App[3344:1584545] progressInfo = {
    CompletedKey = 79;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.914 App[3344:1584713] progressInfo = {
    CompletedKey = 80;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.936 App[3344:1584762] progressInfo = {
    CompletedKey = 81;
    ExpectedKey = 139;
}
2016-05-24 11:41:28.956 App[3344:1584713] progressInfo = {
    CompletedKey = 83;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.211 App[3344:1584586] progressInfo = {
    CompletedKey = 84;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.837 App[3344:1584587] progressInfo = {
    CompletedKey = 85;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.851 App[3344:1584713] progressInfo = {
    CompletedKey = 87;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.903 App[3344:1584762] progressInfo = {
    CompletedKey = 88;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.910 App[3344:1584713] progressInfo = {
    CompletedKey = 89;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.969 App[3344:1584713] progressInfo = {
    CompletedKey = 90;
    ExpectedKey = 139;
}
2016-05-24 11:41:40.983 App[3344:1584775] progressInfo = {
    CompletedKey = 91;
    ExpectedKey = 139;
}
2016-05-24 11:41:41.081 App[3344:1584586] progressInfo = {
    CompletedKey = 92;
    ExpectedKey = 139;
}
2016-05-24 11:41:41.100 App[3344:1584713] progressInfo = {
    CompletedKey = 93;
    ExpectedKey = 139;
}
2016-05-24 11:41:41.116 App[3344:1584762] progressInfo = {
    CompletedKey = 94;
    ExpectedKey = 139;
}
2016-05-24 11:41:41.119 App[3344:1584762] progressInfo = {
    CompletedKey = 95;
    ExpectedKey = 139;
}
2016-05-24 11:41:52.281 App[3344:1584713] progressInfo = {
    CompletedKey = 96;
    ExpectedKey = 139;
}
2016-05-24 11:41:52.918 App[3344:1584762] progressInfo = {
    CompletedKey = 97;
    ExpectedKey = 139;
}
2016-05-24 11:41:52.955 App[3344:1584586] progressInfo = {
    CompletedKey = 98;
    ExpectedKey = 139;
}
2016-05-24 11:41:52.962 App[3344:1584762] progressInfo = {
    CompletedKey = 99;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.035 App[3344:1584777] progressInfo = {
    CompletedKey = 100;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.051 App[3344:1584713] progressInfo = {
    CompletedKey = 101;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.096 App[3344:1584777] progressInfo = {
    CompletedKey = 102;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.112 App[3344:1584586] progressInfo = {
    CompletedKey = 103;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.212 App[3344:1584775] progressInfo = {
    CompletedKey = 104;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.232 App[3344:1584775] progressInfo = {
    CompletedKey = 105;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.245 App[3344:1584775] progressInfo = {
    CompletedKey = 106;
    ExpectedKey = 139;
}
2016-05-24 11:41:53.253 App[3344:1584713] progressInfo = {
    CompletedKey = 107;
    ExpectedKey = 139;
}
2016-05-24 11:42:04.361 App[3344:1584775] progressInfo = {
    CompletedKey = 108;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.003 App[3344:1584777] progressInfo = {
    CompletedKey = 109;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.070 App[3344:1584713] progressInfo = {
    CompletedKey = 110;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.096 App[3344:1584713] progressInfo = {
    CompletedKey = 111;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.140 App[3344:1584797] progressInfo = {
    CompletedKey = 112;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.151 App[3344:1584797] progressInfo = {
    CompletedKey = 113;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.190 App[3344:1584777] progressInfo = {
    CompletedKey = 114;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.212 App[3344:1584797] progressInfo = {
    CompletedKey = 115;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.326 App[3344:1584775] progressInfo = {
    CompletedKey = 116;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.367 App[3344:1584825] progressInfo = {
    CompletedKey = 117;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.376 App[3344:1584825] progressInfo = {
    CompletedKey = 118;
    ExpectedKey = 139;
}
2016-05-24 11:42:05.385 App[3344:1584775] progressInfo = {
    CompletedKey = 119;
    ExpectedKey = 139;
}
2016-05-24 11:42:16.434 App[3344:1584797] progressInfo = {
    CompletedKey = 120;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.105 App[3344:1584797] progressInfo = {
    CompletedKey = 121;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.164 App[3344:1584797] progressInfo = {
    CompletedKey = 122;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.194 App[3344:1584797] progressInfo = {
    CompletedKey = 123;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.230 App[3344:1584777] progressInfo = {
    CompletedKey = 124;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.254 App[3344:1584777] progressInfo = {
    CompletedKey = 125;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.290 App[3344:1584777] progressInfo = {
    CompletedKey = 126;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.296 App[3344:1584777] progressInfo = {
    CompletedKey = 127;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.419 App[3344:1584713] progressInfo = {
    CompletedKey = 128;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.487 App[3344:1584825] progressInfo = {
    CompletedKey = 129;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.490 App[3344:1584825] progressInfo = {
    CompletedKey = 130;
    ExpectedKey = 139;
}
2016-05-24 11:42:17.496 App[3344:1584825] progressInfo = {
    CompletedKey = 131;
    ExpectedKey = 139;
}
2016-05-24 11:42:28.506 App[3344:1584797] progressInfo = {
    CompletedKey = 132;
    ExpectedKey = 139;
}
2016-05-24 11:42:29.187 App[3344:1584797] progressInfo = {
    CompletedKey = 133;
    ExpectedKey = 139;
}
2016-05-24 11:42:29.238 App[3344:1584713] progressInfo = {
    CompletedKey = 134;
    ExpectedKey = 139;
}
2016-05-24 11:42:29.281 App[3344:1584825] progressInfo = {
    CompletedKey = 135;
    ExpectedKey = 139;
}
2016-05-24 11:42:29.300 App[3344:1584713] progressInfo = {
    CompletedKey = 136;
    ExpectedKey = 139;
}
2016-05-24 11:42:29.345 App[3344:1584713] progressInfo = {
    CompletedKey = 137;
    ExpectedKey = 139;
}
2016-05-24 11:42:29.382 App[3344:1584713] progressInfo = {
    CompletedKey = 138;
    ExpectedKey = 139;
}


Where the `CBL_Puller` WARNING happened above we expected to receive `self.pullReplication.status ==kCBLReplicationStopped` and `self.pushReplication.status == kCBLReplicationStopped` with `lastError` set.  However as shown above the progress of the replication kept moving forward (albeit slower) and we did eventually receive `kCBLReplicationStopped` but without `lastError` and it looks like a successful replication occurred even though a decent amount of the document are missing.

David Quon

unread,
Jul 8, 2016, 7:10:43 PM7/8/16
to Couchbase Mobile
This behavior seems to be what's expected after moving forward from CBL 1.0.4 to 1.2.2.  Completing issue as upgrading fixed inconsistent behavior.
Reply all
Reply to author
Forward
0 new messages