Push sync works, pull sync does not

mobile

#1

I have an issue with pull syncing, that I think is in my swift code or library.
This used to work, and somehow I’ve broken it and I don’t know how because (I think) the basic sync code has been untouched. I’m hoping that someone can provide a little guidance as to how to debug syncing and to interpret the logs.

Background
I have 3 types of data:

  • public. Your public PKE keys and password salts. The channel is “keys”, and everyone including GUEST has access.
  • private. Your data and private PKE keys. The channel is the same as your uid, and only you have access.
  • shared. Any info I share with you, by adding your uid (channel ID) to the channels for that doc.

I can create a user:

  • user account is set up in Sync Gateway. I can see it in the web UI.
  • a public record is created with channel [“keys”] - GUEST can access this. I can see that in the web UI
  • a set of private records are created with channel [my uid], and only I can access these.

In the sync gateway UI I can see the user, the channels and the right data shown in the channel itself (channels tab). This all looks good.

I can also test the data by running this on the command line:

curl -X GET http://localhost:4984/<db>/_changes

This returns only the public data, because its logging in as guest.
I can also do this:

curl -X GET http://<uid>:<pwd>@localhost:4984/<db>/_changes?feed=continuous

I can then push some changes from my app, and I can see the changes reflected in the curl output as they happen.

Ok - by now I’m hoping that I have convinced you that the data is structured perfectly in couchbase/sync gateway. :slight_smile: . Push is working perfectly.

The Issue
If I install the app on desktop or mobile “A”, create some data, then install the app on desktop or mobile “B” and enter my ID/pwd, I should have the data sync’d to the new device. This used to work!

But now pull syncing doesn’t seem to work anymore. What happens is nothing is returned to the app and the app and sync_gateway both go into a weird infinite loop.

I hate to dump a ton of code… but this is my sync code (shamelessly copied from sample Grocery App Swift code):

func startSyncProcesses() {
    guard let user = UserManager.user else { abort() }
    
    debugPrint("Starting replication")
    
    _push = setupReplication(gDB.createPushReplication(gServerURL))
    _pull = setupReplication(gDB.createPullReplication(gServerURL))
    var auth: CBLAuthenticatorProtocol?
    auth = CBLAuthenticator.basicAuthenticatorWithName(user.id, password: user.pass_hash)
    _push.authenticator = auth
    _pull.authenticator = auth
    //  Only pull files with my id in their channels (note: we dont want to pull keys, even though
    //  I have access to them). Push, on the other hand, is for everything I have access to.
    _pull.channels = [user.id]    // channel id == user.id
    _push.start()
    _pull.start()
}
func setupReplication(replication: CBLReplication!) -> CBLReplication! {
    if replication != nil {
        replication.continuous = true
        NSNotificationCenter.defaultCenter().addObserver(self,
                                                         selector: #selector(MainView.replicationProgress(_:)),
                                                         name: kCBLReplicationChangeNotification,
                                                         object: replication)
    }
    return replication
}
func replicationProgress(n: NSNotification) {
    debugPrint("ReplicationProcess")
    if (_pull.status == CBLReplicationStatus.Active || _push.status == CBLReplicationStatus.Active) {
        debugPrint("Sync is active")
        // Sync is active -- aggregate the progress of both replications and compute a fraction:
        let completed = _pull.completedChangesCount + _push.completedChangesCount
        let total = _pull.changesCount + _push.changesCount
        debugPrint("SYNC progress: \(completed) / \(total)")
        notesListView!.syncStatusImage.hidden = false
        notesListView!.syncStatusImage.image = NSImage(named:"NSRefreshTemplate")
        let percent: Int = total == 0 ? 100 : Int(completed*100/total)
        notesListView!.syncStatusImage.toolTip = "Sync in progress...\(percent)"
    } else {
        // Sync is idle -- hide the progress bar:
        debugPrint("Sync is idle")
        notesListView!.syncStatusImage.hidden = true
    }
    
    // Check for any sync errors
    let error = _pull.lastError ?? _push.lastError
    if error != nil {
        debugPrint("Error syncing", error)
        notesListView!.syncStatusImage.hidden = false
        notesListView!.syncStatusImage.image = NSImage(named:"NSCaution")
        notesListView!.syncStatusImage.toolTip = "Error connecting to sync server"
    }
    
}

Push works perfectly, but pull does not. If I have 100 records to push, I can see the notifications happen as push syncing goes ahead.

When pull syncing starts, here is the debug log created by the code above (i.e. sync reports nothing to do).

"Starting replication"
"ReplicationProcess"
"Sync is idle"
"ReplicationProcess"
"Sync is idle"
"ReplicationProcess"
"Sync is idle"
"ReplicationProcess"
"Sync is active"
"SYNC progress: 0 / 0"
"ReplicationProcess"
"Sync is idle"

On the sync server… the following log entries are created:
First I pull the public key information (ID is -key). This must be done as guest as I haven’t established auth yet. I do this with a direct http GET to the sync gateway

2016-06-14T12:25:11.808+12:00 HTTP:  #961: GET /private/AXYg7VG9edz6VlUGGNY1qn-key
2016-06-14T12:25:11.809+12:00 HTTP+: #961:     --> 200   (1.7 ms)

Then I use the ID/pwd to pull the first block of private information, again via a GET. This works and proves that I have the right ID and password.

2016-06-14T12:25:11.833+12:00 HTTP:  #962: GET /private/AXYg7VG9edz6VlUGGNY1qn  (as AXYg7VG9edz6VlUGGNY1qn)
2016-06-14T12:25:11.835+12:00 HTTP+: #962:     --> 200   (3.1 ms)

I’m guessing the “(as AXYg7VG9edz6VlUGGNY1qn)” implies that auth worked.
Next I start the sync process using the code above. Here is what happens at the server:

2016-06-14T12:25:12.131+12:00 HTTP:  #963: POST /private/_changes
2016-06-14T12:25:12.131+12:00 Changes+: Int sequence multi changes feed...
2016-06-14T12:25:12.131+12:00 Changes: MultiChangesFeed({AXYg7VG9edz6VlUGGNY1qn}, {Since:0 Limit:0 Conflicts:true IncludeDocs:false Wait:false Continuous:false Terminator:0xc820bae3c0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:true}) ... 
2016-06-14T12:25:12.131+12:00 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{} ... 
2016-06-14T12:25:12.131+12:00 Changes+: MultiChangesFeed sending &{Seq:1 ID:_user/GUEST Deleted:false Removed:{} Doc:map[] Changes:[] Err:<nil> allRemoved:false branched:false} 
2016-06-14T12:25:12.132+12:00 Changes: MultiChangesFeed done 
2016-06-14T12:25:12.132+12:00 HTTP+: #963:     --> 200 OK  (0.0 ms)
2016-06-14T12:25:12.136+12:00 HTTP:  #964: POST /private/_changes
2016-06-14T12:25:12.136+12:00 Changes+: Int sequence multi changes feed...
2016-06-14T12:25:12.136+12:00 Changes: MultiChangesFeed({AXYg7VG9edz6VlUGGNY1qn}, {Since:1 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc820bae8a0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ... 
2016-06-14T12:25:12.137+12:00 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{} ... 
2016-06-14T12:25:12.137+12:00 Changes+: MultiChangesFeed waiting... 
2016-06-14T12:25:12.137+12:00 Changes+: Waiting for "private"'s count to pass 12
2016-06-14T12:25:12.137+12:00 Changes: MultiChangesFeed done 
2016-06-14T12:25:12.137+12:00 HTTP+: #964:     --> 200 OK  (0.0 ms)

This repeats for ever and very very fast (you can see its happening every few ms).
My Questions:

  • Does “MultiChangesFeed({AXYg7VG9edz6VlUGGNY1qn}” refer to the channel? If so, that’s correct.
  • Does “ID:_user/GUEST” imply auth has failed and sync_gateway is falling back to using guest? As you can see from my code above - I am using a basic auth object for push and pull, and it does work for the push.
  • It says "Continuous:false ", but I set that to true in the code
  • Is the sync upset by a previous call to the REST API (I use NSURLSessionConfiguration.ephemeralSessionConfiguration(), so it “shouldn’t”.
  • Why does a failed pull sync cause such a crazy loop?

Is there anything else I can look for that might help sort this out?

Many thanks for any advice you can provide.
Cheers.
Paul

p.s. tried this with sync_gateway on mac and Ubuntu… same results. Also tried deleting and recreating the bucket. I’m positive this is something in my code… but what?


SG endless loop
#2

Also… here’s my config.json:

{
"log": ["*"],
"interface": ":4984",
"adminInterface": ":4985",
"databases": {
    "private": {
        "users": {
                "GUEST": {"disabled": false, "admin_channels": ["keys"] }
        },
    "server": "http://localhost:8091",
    "username": "private",
    "password": "password",
        "bucket": "private",
        "sync": ` function(doc, oldDoc) { channel(doc.channels); } `
        }
    }
}

#3

Let’s look at the logs from the app, with SyncVerbose and ChangeTracker logs enabled. (If you don’t know how to turn on logging, look in the CBL-iOS wiki on Github.)


#4

Hi @jens .
Thanks for getting back to me.
I’ve enabled “SyncVerbose” and “ChangeTracker” logging.
It almost immediately entered a very high speed loop.

Here’s the first few cycles - the first 5 messages are from my app - in the notification callback. The rest is from CBL. There’s more if you need it.

"Starting replication"
"ReplicationProcess"
"Sync is idle"
"ReplicationProcess"
"Sync is idle"
16:54:10.165‖ SyncVerbose: CBLRestPusher[http://localhost:4984/private/]: Received 0 revs
16:54:10.166‖ SyncVerbose: CBLRestPusher[http://localhost:4984/private/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
16:54:10.168‖ SyncVerbose: CBLRestPuller[http://localhost:4984/private/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
16:54:10.169‖ SyncVerbose: CBLRestPuller[http://localhost:4984/private/] starting ChangeTracker: mode=0, since=(null)
16:54:10.170‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Starting...
16:54:10.170‖ SyncVerbose: CBLSocketChangeTracker[0x6000001a2f40 private]: POST //localhost:4984/private/_changes
16:54:10.172‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    SOCKSEnable = 0;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en5 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
            SOCKSEnable = 0;
        };
    };
}
16:54:10.173‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Started... <http://localhost:4984/private/_changes>
16:54:10.173‖ SyncVerbose: CBLRestPuller[http://localhost:4984/private/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
16:54:10.174‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Event 1 on <__NSCFInputStream: 0x60000010a320>
16:54:10.182‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: EndEncountered <__NSCFInputStream: 0x60000010a320>
16:54:10.182‖ SyncVerbose: CBLRestPuller[http://localhost:4984/private/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
16:54:10.183‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Starting...
16:54:10.183‖ SyncVerbose: CBLSocketChangeTracker[0x6000001a2f40 private]: POST //localhost:4984/private/_changes
16:54:10.183‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    SOCKSEnable = 0;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en5 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
            SOCKSEnable = 0;
        };
    };
}
16:54:10.184‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Started... <http://localhost:4984/private/_changes>
16:54:10.192‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Event 1 on <__NSCFInputStream: 0x60800010be20>
16:54:10.197‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: EndEncountered <__NSCFInputStream: 0x60800010be20>
16:54:10.197‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Starting...
16:54:10.198‖ SyncVerbose: CBLSocketChangeTracker[0x6000001a2f40 private]: POST //localhost:4984/private/_changes
16:54:10.198‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    SOCKSEnable = 0;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en5 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
            SOCKSEnable = 0;
        };
    };
}
16:54:10.204‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Started... <http://localhost:4984/private/_changes>
16:54:10.205‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Event 1 on <__NSCFInputStream: 0x6000001041d0>
16:54:10.210‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: EndEncountered <__NSCFInputStream: 0x6000001041d0>
16:54:10.212‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Starting...
16:54:10.212‖ SyncVerbose: CBLSocketChangeTracker[0x6000001a2f40 private]: POST //localhost:4984/private/_changes
16:54:10.213‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    SOCKSEnable = 0;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en5 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
            SOCKSEnable = 0;
        };
    };
}
16:54:10.213‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Started... <http://localhost:4984/private/_changes>
16:54:10.214‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Event 1 on <__NSCFInputStream: 0x6000001041d0>
16:54:10.218‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: EndEncountered <__NSCFInputStream: 0x6000001041d0>
16:54:10.219‖ ChangeTracker: CBLSocketChangeTracker[0x6000001a2f40 private]: Starting...
16:54:10.220‖ SyncVerbose: CBLSocketChangeTracker[0x6000001a2f40 private]: POST //localhost:4984/private/_changes
16:54:10.221‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    SOCKSEnable = 0;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en5 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
            SOCKSEnable = 0;
        };
    };
}

#5

Having a look at the data… I’m going to hazard a wild guess its something to do with the client having “continuous=true” and the server receiving “continuous= false”. So perhaps the server responds immediately and closes. The client thinks it should be a long connection, and so it restarts the call. You can see from the client side the sequence:

On the server the sequence looks like:

  • POST /private/_changes
  • Int sequence multi changes feed…
  • Changes: MultiChangesFeed({AXYg7VG9edz6VlUGGNY1qn}, {Since:1 Limit:0 Conflicts:true IncludeDocs:false Wait:true . Continuous:false Terminator:0xc820bae8a0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) …
  • 2016-06-14T12:25:12.137+12:00 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{} …
  • Changes+: MultiChangesFeed waiting…
  • Changes+: Waiting for “private”'s count to pass 12
  • Changes: MultiChangesFeed done
    and then repeat…

Weird.
Cheers.
Paul


#6

What versions of the software are you using? CBL should be using WebSockets to access the changes feed, but the SG logs don’t show that, which is weird.

I’m going to hazard a wild guess its something to do with the client having “continuous=true” and the server receiving “continuous= false”.

Nope. CBL/iOS never uses the feed=continuous option to _changes, for complicated reasons.


#7

1.2.1 of sync gateway on both Mac and Ubuntu.

Couchbase:

  • 4.5.0-2203 on mac and
  • 4.0 on Ubuntu

The CouchbaseLite.Framework is 1.2.1 as well.

W.R.T. the issue of web sockets…
When I generated that debug log, I was running Couchbase+ sync g/w locally on the Mac. I’ll switch to couchbase+sync g/w running on Ubuntu and see if that makes a difference.

Thanks for the input.
Cheers
Paul.


#8

Here is the log from running the app on a mac against Couchbase+SyncGW on an Ubuntu server (i.e. not localhost):

"Starting replication"
"ReplicationProcess"
"Sync is idle"
"ReplicationProcess"
"Sync is idle"
09:21:52.865‖ SyncVerbose: CBLRestPusher[http://192.168.1.118:4984/private/]: Received 0 revs
09:21:52.865‖ SyncVerbose: CBLRestPusher[http://192.168.1.118:4984/private/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
09:21:52.867‖ SyncVerbose: CBLRestPuller[http://192.168.1.118:4984/private/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
09:21:52.867‖ SyncVerbose: CBLRestPuller[http://192.168.1.118:4984/private/] starting ChangeTracker: mode=0, since=(null)
09:21:52.868‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Starting...
09:21:52.869‖ SyncVerbose: CBLSocketChangeTracker[0x6080001ad200 private]: POST //192.168.1.118:4984/private/_changes
09:21:52.871‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en3 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
    };
}
09:21:52.872‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Started... <http://192.168.1.118:4984/private/_changes>
09:21:52.873‖ SyncVerbose: CBLRestPuller[http://192.168.1.118:4984/private/]: postProgressChanged (0/0, active=1 (batch=0, net=1), online=1)
09:21:52.873‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Event 1 on <__NSCFInputStream: 0x60000010b6d0>
09:21:52.884‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: EndEncountered <__NSCFInputStream: 0x60000010b6d0>
09:21:52.884‖ SyncVerbose: CBLRestPuller[http://192.168.1.118:4984/private/]: postProgressChanged (0/0, active=0 (batch=0, net=0), online=1)
09:21:52.885‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Starting...
09:21:52.885‖ SyncVerbose: CBLSocketChangeTracker[0x6080001ad200 private]: POST //192.168.1.118:4984/private/_changes
09:21:52.885‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en3 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
    };
}
09:21:52.886‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Started... <http://192.168.1.118:4984/private/_changes>
09:21:52.898‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Event 1 on <__NSCFInputStream: 0x60000010b6d0>
09:21:52.920‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: EndEncountered <__NSCFInputStream: 0x60000010b6d0>
09:21:52.921‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Starting...
09:21:52.921‖ SyncVerbose: CBLSocketChangeTracker[0x6080001ad200 private]: POST //192.168.1.118:4984/private/_changes
09:21:52.921‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en3 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
    };
}
09:21:52.926‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Started... <http://192.168.1.118:4984/private/_changes>
09:21:52.926‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Event 1 on <__NSCFInputStream: 0x60000010b6d0>
09:21:52.932‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: EndEncountered <__NSCFInputStream: 0x60000010b6d0>
09:21:52.933‖ ChangeTracker: CBLSocketChangeTracker[0x6080001ad200 private]: Starting...
09:21:52.933‖ SyncVerbose: CBLSocketChangeTracker[0x6080001ad200 private]: POST //192.168.1.118:4984/private/_changes
09:21:52.934‖ ChangeTracker: Changes feed using proxy settings {
    ExceptionsList =     (
        "*.local",
        "169.254/16"
    );
    FTPPassive = 1;
    "__SCOPED__" =     {
        en0 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
        en3 =         {
            ExceptionsList =             (
                "*.local",
                "169.254/16"
            );
            FTPPassive = 1;
        };
    };
}

And here is first few cycles from the server logs…

First - fetch public info

09:21:52.530046 2016-06-15T09:21:52.529+12:00 Bucket: Update("_sync:user:", 0, ...) --> CAS quit [13.30914ms]
09:21:52.532552 2016-06-15T09:21:52.532+12:00 HTTP:  #958: GET /private/2ftYeqTKJhOzNbGAR2M0dr-key
09:21:52.540467 2016-06-15T09:21:52.540+12:00 Bucket: Get("2ftYeqTKJhOzNbGAR2M0dr-key") [6.61907ms]
09:21:52.540900 2016-06-15T09:21:52.540+12:00 HTTP+: #958:     --> 200   (27.7 ms)

Auth and fetch private info

09:21:52.572521 2016-06-15T09:21:52.572+12:00 Bucket: Update("_sync:user:2ftYeqTKJhOzNbGAR2M0dr", 0, ...) --> CAS quit [3.391332ms]
09:21:52.574222 2016-06-15T09:21:52.574+12:00 HTTP:  #959: GET /private/2ftYeqTKJhOzNbGAR2M0dr  (as 2ftYeqTKJhOzNbGAR2M0dr)
09:21:52.575314 2016-06-15T09:21:52.575+12:00 Bucket: Get("2ftYeqTKJhOzNbGAR2M0dr") [991.762µs]
09:21:52.579907 2016-06-15T09:21:52.579+12:00 HTTP+: #959:     --> 200   (10.9 ms)

Start the sync…

09:21:52.906418 2016-06-15T09:21:52.906+12:00 Bucket: Update("_sync:user:", 0, ...) --> CAS quit [374.535µs]
09:21:52.906491 2016-06-15T09:21:52.906+12:00 HTTP:  #960: POST /private/_changes
09:21:52.907628 2016-06-15T09:21:52.907+12:00 Changes+: Int sequence multi changes feed...
09:21:52.907708 2016-06-15T09:21:52.907+12:00 Changes: MultiChangesFeed({2ftYeqTKJhOzNbGAR2M0dr}, {Since:0 Limit:0 Conflicts:true IncludeDocs:false Wait:false Continuous:false Terminator:0xc820e50420 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:true}) ... 
09:21:52.912287 2016-06-15T09:21:52.909+12:00 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{} ... 
09:21:52.912571 2016-06-15T09:21:52.912+12:00 Changes+: MultiChangesFeed sending &{Seq:1 ID:_user/GUEST Deleted:false Removed:{} Doc:map[] Changes:[] Err:<nil> allRemoved:false branched:false} 
09:21:52.912717 2016-06-15T09:21:52.912+12:00 Changes: MultiChangesFeed done 
09:21:52.913103 2016-06-15T09:21:52.913+12:00 HTTP+: #960:     --> 200 OK  (0.0 ms)
09:21:52.930203 2016-06-15T09:21:52.930+12:00 Bucket: Update("_sync:user:", 0, ...) --> CAS quit [395.108µs]
09:21:52.930429 2016-06-15T09:21:52.930+12:00 HTTP:  #961: POST /private/_changes
09:21:52.930615 2016-06-15T09:21:52.930+12:00 Changes+: Int sequence multi changes feed...
09:21:52.930749 2016-06-15T09:21:52.930+12:00 Changes: MultiChangesFeed({2ftYeqTKJhOzNbGAR2M0dr}, {Since:1 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc820e506c0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ... 
09:21:52.943134 2016-06-15T09:21:52.943+12:00 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{} ... 
09:21:52.943197 2016-06-15T09:21:52.943+12:00 Changes+: MultiChangesFeed waiting... 
09:21:52.943231 2016-06-15T09:21:52.943+12:00 Changes+: Waiting for "private"'s count to pass 11
09:21:52.943249 2016-06-15T09:21:52.943+12:00 Changes: MultiChangesFeed done 
09:21:52.949632 2016-06-15T09:21:52.949+12:00 HTTP+: #961:     --> 200 OK  (0.0 ms)
09:21:52.961390 2016-06-15T09:21:52.961+12:00 Bucket: Update("_sync:user:", 0, ...) --> CAS quit [616.738µs]
09:21:52.961450 2016-06-15T09:21:52.961+12:00 HTTP:  #962: POST /private/_changes
09:21:52.961525 2016-06-15T09:21:52.961+12:00 Changes+: Int sequence multi changes feed...
09:21:52.961574 2016-06-15T09:21:52.961+12:00 Changes: MultiChangesFeed({2ftYeqTKJhOzNbGAR2M0dr}, {Since:1 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:false Terminator:0xc820cc0ae0 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ... 
09:21:52.962528 2016-06-15T09:21:52.962+12:00 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{} ... 
09:21:52.962554 2016-06-15T09:21:52.962+12:00 Changes+: MultiChangesFeed waiting... 
09:21:52.962567 2016-06-15T09:21:52.962+12:00 Changes+: Waiting for "private"'s count to pass 11
09:21:52.962576 2016-06-15T09:21:52.962+12:00 Changes: MultiChangesFeed done 
09:21:52.962599 2016-06-15T09:21:52.962+12:00 HTTP+: #962:     --> 200 OK  (0.0 ms)

Which then repeats for ever…

Do you have any ideas as to where else I can look?

Since I have replicated this on Couchbase 4.5 on Mac and and 4.0 on Ubuntu, with sync g/w 1.2.1 on both, I’m going to guess that the common factor is inside my code or the Framework. I’m going to redownload/install the framework…

Again… thanks for looking at this.

Cheers.
Paul.


#9

Ok. Found the problem.
Copying over a freshly downloaded copy of CouchbaseLite.Framework file, everything started working.

Checking the difference between the two, I can see that I was in fact running 1.2.0 of the Framework rather than 1.2.1. I’ve got to hang my head in shame here - I had not double checked the version.

I must have been running 1.2.1 a week ago when syncing was fine. Perhaps some time in the last week I somehow reverted? Or perhaps my copy of 1.2.0 got corrupted, because it seems strange that 1.2.0 would fail so badly?

Now that its all working again, I’m back to writing UI tests (yay :slight_smile: ).
Again, thank for your help with this.
Cheers.
Paul.


#10

There were some serious replication bugs fixed in 1.2.1, mostly involving CouchDB servers, but IIRC there may have been one with SG. The fact that your server database contained nothing except a change to a _user record may have triggered it.

Anyway, glad you’re back in business!