Couchbase Lite iOS Replication Help

mike

unread,

May 20, 2013, 3:36:39 PM5/20/13

to mobile-c...@googlegroups.com

Changes are replicating from my sync_gateway server to my device but changes from my device aren't replicating to the server until I restart the app. I am using a replication filter to keep some changes local but the problem persists even if I remove the filter. Not sure what's going on -- any help would be appreciated.

Here's the log from the first run:

14:08:54.886| Logging mode 2 enabled in domains: {Sync}
14:08:54.926| Sync: ReplicatorManager: Validating CBLRevision[4CEA..7BE7/]: {
continuous = 1;
source = "http://10.200.40.135:3984/g3/";
target = local;
}
14:08:54.928| Sync: ReplicatorManager: {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #1-4d6a76cb9854ffc1b06633df82493d81} was created
14:08:54.928| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STARTING ...
14:08:54.928| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
14:08:54.929| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
14:08:54.929| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Going online
14:08:54.929| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.929| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.929| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #1-4d6a76cb9854ffc1b06633df82493d81} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
"_replication_state" = triggered;
"_replication_state_time" = 1369076934;
}
14:08:54.931| Sync: ReplicatorManager: Validating CBLRevision[500B..8895/]: {
continuous = 1;
source = local;
target = "http://10.200.40.135:3984/g3/";
}
14:08:54.932| Sync: ReplicatorManager: {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #1-9c3c66f3974c95c53660f5c65923cec6} was created
14:08:54.932| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STARTING ...
14:08:54.932| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
14:08:54.932| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
14:08:54.932| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Going online
14:08:54.933| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.933| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.933| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #1-9c3c66f3974c95c53660f5c65923cec6} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
"_replication_state" = triggered;
"_replication_state_time" = 1369076934;
}
14:08:54.946| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #2-a89e2dd777abeec30d47bd72dafe01bd} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:08:54.946| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #2-d8ffabd0b123689c316dd75d4b7978f0} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
}
14:08:54.960| Sync: ReplicatorManager: Validating CBLRevision[500B..8895/]: {
"_id" = "500B5867-25B3-43CF-8AD4-9EB3ED0C8895";
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
"_replication_state_time" = 1369076934;
"_rev" = "2-d8ffabd0b123689c316dd75d4b7978f0";
continuous = 1;
filter = "mobile/filterOutLocalDocuments";
source = local;
target = "http://10.200.40.135:3984/g3/";
}
14:08:54.962| Sync: ReplicatorManager: Restarting replicator for {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #3-ba972e532b004291412ec2cda492a569}
14:08:54.962| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STOPPING...
14:08:54.962| Sync: Stopping 1 remote requests
14:08:54.965| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Error fetching last sequence: The operation couldn’t be completed. (NSURLErrorDomain error -999.)
14:08:54.969| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.969| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STOPPED
14:08:54.969| Replication: CBL_Pusher[http://10.200.40.135:3984/g3/] took 0.037 sec; error=(null)
14:08:54.969| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.969| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.970| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #3-ba972e532b004291412ec2cda492a569} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
"_replication_state" = completed;
"_replication_state_time" = 1369076934;
}
14:08:54.971| Sync: ReplicatorManager: {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #3-ba972e532b004291412ec2cda492a569} was created
14:08:54.971| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STARTING ...
14:08:54.971| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
14:08:54.972| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
14:08:54.972| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Going online
14:08:54.972| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.973| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.973| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #3-ba972e532b004291412ec2cda492a569} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
"_replication_state" = triggered;
"_replication_state_time" = 1369076934;
}
14:08:54.976| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=(null)
14:08:54.979| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=(null)
14:08:54.985| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.986| Sync: ReplicatorManager: Validating CBLRevision[4CEA..7BE7/]: {
"_id" = "4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7";
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
"_replication_state_time" = 1369076934;
"_rev" = "2-a89e2dd777abeec30d47bd72dafe01bd";
continuous = 1;
source = "http://10.200.40.135:3984/g3/";
target = local;
}
14:08:54.987| Sync: ReplicatorManager: Restarting replicator for {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #3-570fadae334a491abf0eae70998e8826}
14:08:54.988| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.988| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STOPPING...
14:08:54.988| Sync: Stopping 0 remote requests
14:08:54.988| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STOPPED
14:08:54.988| Replication: CBL_Puller[http://10.200.40.135:3984/g3/] took 0.060 sec; error=(null)
14:08:54.988| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.988| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:08:54.989| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #3-570fadae334a491abf0eae70998e8826} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
"_replication_state" = completed;
"_replication_state_time" = 1369076934;
}
14:08:54.990| Sync: ReplicatorManager: {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #3-570fadae334a491abf0eae70998e8826} was created
14:08:54.991| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STARTING ...
14:08:54.991| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
14:08:54.992| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
14:08:54.992| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Going online
14:08:54.992| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.992| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:08:54.992| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #3-570fadae334a491abf0eae70998e8826} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
"_replication_state" = triggered;
"_replication_state_time" = 1369076934;
}
14:08:54.995| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #5-529316dc41e5e1a612efad4c1fae2f49} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
}
14:08:54.996| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:08:55.002| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=(null)
14:08:55.297| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Received 24 changes
14:08:55.297| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/24, active=1 (batch=24, net=1), online=1)
14:08:55.297| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Caught up with changes!
14:08:55.298| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:08:55.798| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] queued 24 remote revisions from seq=1 (24 in bulk, 0 individually)
14:08:55.798| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] bulk-fetching 24 remote revisions...
14:08:55.812| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] checking 24 bulk-fetched remote revisions
14:08:56.821| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] inserted 24 revs in 0.009 sec (2774.2/sec)
14:08:56.821| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/24, active=0 (batch=0, net=0), online=1)
14:08:56.821| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (24/24, active=0 (batch=0, net=0), online=1)
14:08:56.822| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:09:01.819| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] checkpointing sequence=24
2013-05-20 14:10:14.035 MyApp[94340:9903] filter for assignment B65B6BFA-991C-41B6-96A6-41F5D5AED69A include? YES
14:10:14.035‖ Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=1, net=0), online=1)
2013-05-20 14:10:14.354 MyApp[94340:9903] filter for user bobbih include? YES

And that's it. I can see that my filter is being called and I can leave the app running in the simulator, but nothing further happens. On restart the documents replicate. Here's the log from the restart:

14:13:17.444| Logging mode 2 enabled in domains: {Sync}
14:13:17.446| Sync: ReplicatorManager scanning existing _replicator docs...
14:13:17.447| Sync: ReplicatorManager: {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} was created
14:13:17.448| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STARTING ...
14:13:17.449| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
14:13:17.544| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
14:13:17.544| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Going online
14:13:17.544| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:13:17.546| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:13:17.546| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:13:17.546| Sync: ReplicatorManager: {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #5-529316dc41e5e1a612efad4c1fae2f49} was created
14:13:17.546| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STARTING ...
14:13:17.546| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
14:13:17.546| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
14:13:17.546| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Going online
14:13:17.547| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:13:17.547| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:13:17.547| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #5-529316dc41e5e1a612efad4c1fae2f49} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
}
14:13:17.547| Sync: ReplicatorManager done scanning.
14:13:17.564| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:13:17.565| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #5-529316dc41e5e1a612efad4c1fae2f49} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
}
14:13:17.586| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=(null)
14:13:17.597| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=24
14:13:17.600| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Received 0 changes
14:13:17.600| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
14:13:17.600| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Caught up with changes!
14:13:17.600| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
14:13:17.601| Sync: ReplicatorManager: Updating {4CEA5CD3-373A-4E5C-A7F2-CC7A2CF37BE7 #5-53d073266772d1c7489e1b268c1b3b27} with {
"_replication_id" = "E7E47B9A-03C3-4C20-B867-74B77806A40A";
}
14:13:17.623| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Sending 2 revisions
14:13:17.623| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/2, active=1 (batch=0, net=1), online=1)
14:13:17.624| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #5-529316dc41e5e1a612efad4c1fae2f49} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
}
14:13:17.630| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (2/2, active=1 (batch=0, net=1), online=1)
14:13:17.631| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (2/2, active=0 (batch=0, net=0), online=1)
14:13:17.631| Sync: ReplicatorManager: Updating {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #5-529316dc41e5e1a612efad4c1fae2f49} with {
"_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
}
14:13:22.620| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] checkpointing sequence=30

Jens Alfke

unread,

May 20, 2013, 4:56:41 PM5/20/13

to mobile-c...@googlegroups.com

On May 20, 2013, at 12:36 PM, mike <lam...@gmail.com> wrote:

> 14:08:54.960| Sync: ReplicatorManager: Validating CBLRevision[500B..8895/]: {
> "_id" = "500B5867-25B3-43CF-8AD4-9EB3ED0C8895";
> "_replication_id" = "0332FDAF-38FC-4525-9672-6D14E5F59878";
> "_replication_state_time" = 1369076934;
> "_rev" = "2-d8ffabd0b123689c316dd75d4b7978f0";
> continuous = 1;
> filter = "mobile/filterOutLocalDocuments";
> source = local;
> target = "http://10.200.40.135:3984/g3/";
> }
> 14:08:54.962| Sync: ReplicatorManager: Restarting replicator for {500B5867-25B3-43CF-8AD4-9EB3ED0C8895 #3-ba972e532b004291412ec2cda492a569}

As near as I can tell, the TDReplication is being told to restart. Are you calling -restart on it?

I’m not sure from these logs what’s going wrong. Could you post some of the code you use to set up the replications?

—Jens

mike

unread,

May 21, 2013, 9:07:37 AM5/21/13

to mobile-c...@googlegroups.com

> Could you post some of the code you use to set up the replications?

Sure thing. Here's the code I'm using:

self.replications = [self.database replicateWithURL:remoteDatabaseURL exclusively:YES];
for (CBLReplication *replication in self.replications) {
replication.continuous = YES;
replication.persistent = YES;
}
[self.replications[0] addObserver:self forKeyPath:kCompletedKeyPath options:0 context:NULL];
[self.replications[1] addObserver:self forKeyPath:kCompletedKeyPath options:0 context:NULL];
[self defineViews];
NSString *filterName = [NSString stringWithFormat:@"%@/%@", kMobileDesignDocumentName, kFilterOutLocalDocuments];
[self.database defineFilter:filterName asBlock:^BOOL(CBLRevision *revision, NSDictionary *params) {
NSNumber *localOnly = [revision.properties objectForKey:kLocalOnly];
BOOL include = !localOnly.boolValue;
NSLog(@"filter for %@ %@ include? %@", revision.properties[@"type"], revision.properties[@"_id"], include ? @"YES" : @"NO");
return include;
}];
((CBLReplication *)self.replications[1]).filter = filterName;

Fwiw, if I comment out the definition and setting of filter, I still get the restart. If I comment out everything after the first line I don't get the restart. The replication doesn't work, presumably because it isn't continuous, but I don't get the restart message:

07:51:23.713| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STARTING ...
07:51:23.714| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
07:51:23.714| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
07:51:23.714| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Going online
07:51:23.715| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
07:51:23.715| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
07:51:23.716| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STARTING ...
07:51:23.716| CBLBasicAuthorizer initWith <http://10.200.40.135:3984/g3/>
07:51:23.716| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Reachability state = <10.200.40.135>:reachable (02)
07:51:23.716| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Going online
07:51:23.717| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
07:51:23.717| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
07:51:23.727| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=(null)
07:51:23.728| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
07:51:23.728| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/] STOPPED
07:51:23.728| Replication: CBL_Pusher[http://10.200.40.135:3984/g3/] took 0.012 sec; error=(null)
07:51:23.728| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
07:51:23.728| Sync: CBL_Pusher[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
07:51:23.731| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Replicating from lastSequence=(null)
07:51:24.003| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Received 24 changes
07:51:24.004| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/24, active=1 (batch=24, net=2), online=1)
07:51:24.004| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: Caught up with changes!
07:51:24.004| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: ChangeTracker stopped; error=(null)
07:51:24.005| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] queued 24 remote revisions from seq=1 (24 in bulk, 0 individually)
07:51:24.005| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] bulk-fetching 24 remote revisions...
07:51:24.018| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] checking 24 bulk-fetched remote revisions
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] inserted 24 revs in 0.009 sec (2807.0/sec)
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/24, active=0 (batch=0, net=0), online=1)
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] STOPPED
07:51:25.027| Replication: CBL_Puller[http://10.200.40.135:3984/g3/] took 1.313 sec; error=(null)
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/] checkpointing sequence=24
07:51:25.027| Sync: CBL_Puller[http://10.200.40.135:3984/g3/]: postProgressChanged (24/0, active=0 (batch=0, net=0), online=1)

mike

unread,

May 21, 2013, 10:55:14 AM5/21/13

to mobile-c...@googlegroups.com

Looking at CouchChat, it looks like the replication restarts each time it's change. In CouchChat, the pusher is restarted twice:

09:43:41.489| Sync: ReplicatorManager: Validating CBLRevision[6016..FF12/]: {

"_id" = "60169E4E-44C3-40A4-8C74-92F91BC7FF12";

"_replication_id" = "3DDFEB55-0095-4B64-868E-3B61897351AB";

"_replication_state_time" = 1369147421;

"_rev" = "2-5e7a60ec620e9f293b39f6ab83ea4f3d";

continuous = 1;

source = chat;

target = "http://mobile.hq.couchbase.com/chat";

}

09:43:41.489| Sync: ReplicatorManager: Restarting replicator for {60169E4E-44C3-40A4-8C74-92F91BC7FF12 #3-79a71983d4f07ecea5f1be02c107c60f}

09:43:41.495| Sync: CBL_Pusher[http://mobile.hq.couchbase.com/chat] STOPPING...

09:43:41.495| Sync: CBL_Pusher[http://mobile.hq.couchbase.com/chat] STOPPED

and later

09:43:57.313| Sync: ReplicatorManager: Validating CBLRevision[6016..FF12/]: {

"_id" = "60169E4E-44C3-40A4-8C74-92F91BC7FF12";

"_replication_id" = "3DDFEB55-0095-4B64-868E-3B61897351AB";

"_replication_state_time" = 1369147421;

"_rev" = "5-dafc8fae3869a1221e38fe41030bf05e";

continuous = 1;

source = chat;

target = {

auth = {

persona = {

email = "<valid e-mail address>";

};

url = "http://mobile.hq.couchbase.com/chat";

};

}

09:43:57.313| Sync: ReplicatorManager: Restarting replicator for {60169E4E-44C3-40A4-8C74-92F91BC7FF12 #6-7eddf66d527c9d2f594d592e29a46748}

09:43:57.313| Sync: CBL_Pusher[http://mobile.hq.couchbase.com/chat] STOPPING...

09:43:57.313| Sync: Stopping 0 remote requests

09:43:57.313| Sync: CBL_Pusher[http://mobile.hq.couchbase.com/chat] STOPPED

Jens Alfke

unread,

May 21, 2013, 11:59:26 AM5/21/13

to mobile-c...@googlegroups.com

On May 21, 2013, at 6:07 AM, mike <lam...@gmail.com> wrote:

for (CBLReplication *replication in self.replications) {
replication.continuous = YES;
replication.persistent = YES;
}

...

((CBLReplication *)self.replications[1]).filter = filterName;

The quoted lines are unnecessary except for when the replication is first configured; since the replications are persistent, they keep their settings from one launch to the next. The only reason you need to call -replicateWithURL: is to get pointers to the replication objects so you can observe their status.

However, all those calls should be no-ops on subsequent launches. I just checked the setter methods and they do nothing if the value doesn’t change. So I don’t know why -restart ends up being called. I’ve filed #54.

Looking at CouchChat, it looks like the replication restarts each time it's change. In CouchChat, the pusher is restarted twice:

OK, that will help me debug this. Thanks. I’m not sure this is related to your push replication not progressing, though; even if the replications do restart, that should be harmless (as in CouchChat.) Have you tried ‘SyncVerbose’ logging?

—Jens

mike

unread,

May 21, 2013, 12:41:55 PM5/21/13

to mobile-c...@googlegroups.com

On Tuesday, 21 May 2013 10:59:26 UTC-5, Jens Alfke wrote:

The quoted lines are unnecessary except for when the replication is first configured; since the replications are persistent, they keep their settings from one launch to the next. The only reason you need to call -replicateWithURL: is to get pointers to the replication objects so you can observe their status.

Sorry if I wasn't clear, but the code and logs I posted are from the first launch only. Different code is executed on subsequent launches. I'm running in the simulator and am resetting it between runs.

Have you tried ‘SyncVerbose’ logging?

I'll try that next. Thanks!

Jens Alfke

unread,

May 21, 2013, 1:43:24 PM5/21/13

to mobile-c...@googlegroups.com

On May 21, 2013, at 9:41 AM, mike <lam...@gmail.com> wrote:

Sorry if I wasn't clear, but the code and logs I posted are from the first launch only. Different code is executed on subsequent launches. I'm running in the simulator and am resetting it between runs.

Oh, OK. And the behavior is that on this first launch after reset, the push fails, whereas on any subsequent launch it succeeds.

(If so, what data is there to push on the first launch, before the user’s edited anything? Does the app itself create some data like a user profile?)

—Jens

mike

unread,

May 21, 2013, 3:02:05 PM5/21/13

to mobile-c...@googlegroups.com

On Tuesday, 21 May 2013 12:43:24 UTC-5, Jens Alfke wrote:

Oh, OK. And the behavior is that on this first launch after reset, the push fails, whereas on any subsequent launch it succeeds.

Correct.

(If so, what data is there to push on the first launch, before the user’s edited anything? Does the app itself create some data like a user profile?)

Once launched, the app allows the user to create assignments for other users. This causes an assignment document to be created and the assignee's user document to be updated. With SyncVerbose on, I see additional messages that indicate both documents are queued. But they aren't transmitted until I kill and restart the app.

2013-05-21 13:50:21.838 MyApp[44188:a103] filter for assignment 572183AA-4DDC-4E67-9826-F02CD25A48B8 include? YES

13:50:21.839‖ SyncVerbose: CBL_Pusher[http://couchbase:3984/g3/]: Queuing #29 {572183AA-4DDC-4E67-9826-F02CD25A48B8 #1-ca11b0ea8365af92ab35e99f926a23d0}

13:50:21.839‖ Sync: CBL_Pusher[http://couchbase:3984/g3/]: postProgressChanged (0/0, active=1 (batch=1, net=0), online=1)

2013-05-21 13:50:22.169 MyApp[44188:a103] filter for user bobbih include? YES

13:50:22.169‖ SyncVerbose: CBL_Pusher[http://couchbase:3984/g3/]: Queuing #30 {bobbih #2-654ec6b3b4ec9b0feb7d31454e2d3600}

I'm in the process of porting the SyncManager from CouchChat to my app in the hope that it might help solve (or shed more light on) the problem.

Jens Alfke

unread,

May 21, 2013, 4:04:58 PM5/21/13

to mobile-c...@googlegroups.com

On May 21, 2013, at 12:02 PM, mike <lam...@gmail.com> wrote:

Once launched, the app allows the user to create assignments for other users. This causes an assignment document to be created and the assignee's user document to be updated. With SyncVerbose on, I see additional messages that indicate both documents are queued. But they aren't transmitted until I kill and restart the app.

If the message “Queuing #…” is logged, then there should soon (within 0.5 sec) be a message "*** %@: BEGIN processInbox (%u sequences)”, signaling the callback where the queued revisions get processed (sent). If not, something’s wrong with the CBLBatcher class…

—Jens

mike

unread,

May 22, 2013, 11:50:40 AM5/22/13

to mobile-c...@googlegroups.com

On Tuesday, 21 May 2013 15:04:58 UTC-5, Jens Alfke wrote:

If the message “Queuing #…” is logged, then there should soon (within 0.5 sec) be a message "*** %@: BEGIN processInbox (%u sequences)”, signaling the callback where the queued revisions get processed (sent). If not, something’s wrong with the CBLBatcher class…

Thanks for the insight. I did some debugging and CBLBatcher is working correctly when it's called from the main queue (e.g. on startup) but not when called from a background queue. Specifically when called from a background queue the selector scheduled by[CBLBatcher scheduleWithDelay:] is never called -- presumably because it requires an NSRunLoop that is never run.

The updates I'm making can take a couple of seconds (at least they did under TouchDB) so I make them asynchronously like this:

dispatch_async(dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0), ^{

// Update model objects here.

}

I found that if I remove the dispatch_async() from my code or change [CBLBatcher scheduleWithDelay:] as below to perform the selector on the main queue, everything works fine.

dispatch_async(dispatch_get_main_queue(), ^{

[selfperformSelector: @selector(processNow) withObject: nilafterDelay: delay];

});

It also works if I add [[NSRunLoop currentRunLoop] run] at the end of my dispatch_async.

Jens Alfke

unread,

May 22, 2013, 1:24:22 PM5/22/13

to mobile-c...@googlegroups.com

On May 22, 2013, at 8:50 AM, mike <lam...@gmail.com> wrote:

> Thanks for the insight. I did some debugging and CBLBatcher is working correctly when it's called from the main queue (e.g. on startup) but not when called from a background queue. Specifically when called from a background queue the selector scheduled by[CBLBatcher scheduleWithDelay:] is never called -- presumably because it requires an NSRunLoop that is never run.

CBLBatcher, like all the replicator code, has to be run on a thread with a runloop. That’s part of what CBLServer is for — it manages such a thread for the replicator to run on. If the replicator ever ends up running on a thread other than the one run by CBLServer, that would be a serious bug.

> The updates I'm making can take a couple of seconds (at least they did under TouchDB) so I make them asynchronously like this:
>
> dispatch_async(dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_DEFAULT, 0), ^{
> // Update model objects here.
> }

Yikes! You can’t do that, because CBL is not thread-safe. If you want to call CBL from a different thread (or dispatch queue) you’ll need to make a new object tree starting with a copied CBLManager.

—Jens

mike

unread,

May 22, 2013, 1:31:05 PM5/22/13

to mobile-c...@googlegroups.com

Good to know. Thanks!

Jens Alfke

unread,

May 22, 2013, 1:36:32 PM5/22/13

to mobile-c...@googlegroups.com

On May 22, 2013, at 10:31 AM, mike <lam...@gmail.com> wrote:

Good to know. Thanks!

Let me know if this doesn’t clear up your initial problem.

FYI, in general you shouldn’t treat any Objective-C API as being thread-safe unless it’s documented as being so. Even lots of core classes like mutable containers aren’t thread-safe, for example.

—Jens

mike

unread,

May 22, 2013, 1:50:50 PM5/22/13

to mobile-c...@googlegroups.com

On Wednesday, 22 May 2013 12:36:32 UTC-5, Jens Alfke wrote:

Let me know if this doesn’t clear up your initial problem.

It does. Thanks!

FYI, in general you shouldn’t treat any Objective-C API as being thread-safe unless it’s documented as being so. Even lots of core classes like mutable containers aren’t thread-safe, for example.

Again good to know. Probably best to document this explicitly in any case. In my experience 'general' knowledge rarely is. Perhaps the batcher could check to see if objects are being queued on the same thread that it was created on and @throw something if not to protect it from noobs like me?

Reply all

Reply to author

Forward