SG not propagating changes to Couchbase lite client


#1

Hi,

I am not sure what I am doing wrong but for some reason I am not able to get my SG to propagate changes down to my client. For my testing, I am using following components:

Couchbase Server: Enterprise Edition 5.5.1 build 3511
Sync Gateway: Enterprise Edition 2.1.0
Couchbase Lite for iOS: 2.1.1 (Swift)

My iOS client establishes websocket connection successfully and it is stable. Also I do see from SG logs that channel is being assigned to my user that I used to login to SG from the client.

I have set up SG such that the channel name and document ID are identical. However, when I make some changes to the document on the Couchbase server console, it appears that the replicator running on the client is not receiving any data although I do see that a new change revision is being created from SG logs.

I have uploaded the access and error logs from SG, client code, xcode console output and SG config file that I used.

Any help would be greatly appreciated.

sgdata.zip (7.0 KB)


#2

Please turn on Couchbase Lite logging. Then you’ll be able to see progress messages from the replicator, which may give you an idea of what’s going on.


#3

Sorry about that. I turned on debug level logging on the Couchbase Lite side for all logging domains. I am attaching both XCode console log and sync gateway error log data. I see PING PONG messages but no change data are coming down in the pipe after I made some changes to the document ‘org1035::conv::1’ from the UI console.

From the logs, I have noticed following error messages from the client. Can these errors be causing this problem? I think this error frame was generated by SG because it wants to let the client know that there was no checkpoint.

sgdata1.zip (5.7 KB)

From Client:

2018-10-10 13:05:35.409348-0500 xxxxxx[6264:158505] CouchbaseLite BLIP Verbose: {BLIPIO#2} Received frame: ERR #1 ----, length 45
2018-10-10 13:05:35.409495-0500 xxxxxx[6264:158505] CouchbaseLite BLIP Verbose: {Connection#1} Receiving ERR #1
2018-10-10 13:05:35.409669-0500 xxxxxx[6264:158505] CouchbaseLite BLIP Verbose: {Connection#1} Finished receiving ERR #1
2018-10-10 13:05:35.409914-0500 xxxxxx[6264:158561] CouchbaseLite Sync Info: {Repl#1} No remote checkpoint

From Sync Gateway:

2018-10-10T18:05:35.295Z [INF] HTTP: #296: GET /messaging/_blipsync (as GUEST)
2018-10-10T18:05:35.295Z [INF] HTTP: #296: --> 401 Login required (0.3 ms)
2018-10-10T18:05:35.365Z [INF] HTTP: #297: GET /messaging/_blipsync (as org1035-user-100)
2018-10-10T18:05:35.366Z [INF] HTTP+: #297: --> 101 [622158d2] Upgraded to BLIP+WebSocket protocol. User:org1035-user-100. (0.0 ms)
2018-10-10T18:05:35.366Z [INF] WS: [622158d2] Start BLIP/Websocket handler
2018-10-10T18:05:35.366Z [DBG] WS+: [622158d2] Sender starting
2018-10-10T18:05:35.397Z [DBG] WS+: [622158d2] Received frame: MSG#1 (flags= 0, length=62)
2018-10-10T18:05:35.397Z [DBG] WSFrame+: [622158d2] Incoming BLIP Request: MSG#1
2018-10-10T18:05:35.397Z [INF] SyncMsg: [622158d2] #1: Type:getCheckpoint Client:cp-hksWos+AwoM7Rb9/G+ISAXS4lao= User:org1035-user-100
2018-10-10T18:05:35.397Z [DBG] SyncMsg+: [622158d2] #1: Type:getCheckpoint Client:cp-hksWos+AwoM7Rb9/G+ISAXS4lao= User:org1035-user-100
2018-10-10T18:05:35.397Z [INF] SyncMsg: [622158d2] #1: Type:getCheckpoint --> 404 missing Time:240.448µs User:org1035-user-100
2018-10-10T18:05:35.397Z [DBG] SyncMsg+: [622158d2] #1: Type:getCheckpoint --> 404 missing Time:240.448µs User:org1035-user-100
2018-10-10T18:05:35.397Z [DBG] WS+: [622158d2] Push ERR#1
2018-10-10T18:05:35.397Z [DBG] WS+: [622158d2] Sending frame: ERR#1 (flags= 10, size= 41)
2018-10-10T18:05:35.422Z [DBG] WS+: [622158d2] Received frame: MSG#2 (flags= 0, length=62)
2018-10-10T18:05:35.422Z [DBG] WS+: [622158d2] Received frame: MSG#3! (flags= 110000, length=26)


#4

The error is just a [BLIP equivalent of a] 404 Not Found, since there is no checkpoint doc on the server yet for this replication. That’s normal.

I don’t see anything odd in the logs. They just indicate that there are no docs matching any of the requested channels. Particularly this sequence from SG:

2018-10-10T18:05:35.423Z [INF] Cache: getCachedChanges("org1035::conv::6", 9:0) --> 0 changes valid from #1
2018-10-10T18:05:35.423Z [DBG] Changes+: [changesFeed] Found 0 changes for channel org1035::conv::6
...
2018-10-10T18:05:35.423Z [DBG] Changes+: MultiChangesFeed sending {Seq:22, ID:_user/org1035-user-100, Changes:[]}   (to org1035-user-100)
2018-10-10T18:05:35.423Z [DBG] Changes+: MultiChangesFeed waiting...   (to org1035-user-100)
2018-10-10T18:05:35.423Z [DBG] Changes+: No new changes to send to change listener.  Waiting for "messaging"'s count to pass 28

I would guess that the docs aren’t being assigned to the right channels.


#5

Thank you for your reply jens.

The changes were made to the doc ID, “org1035::conv::1”, at around 18:07:22 UTC from the Couchbase UI console. Also the channel name is identical (“org1035::conv::1”). In the same server error log file from my previous post (sgdata1.zip), you will see that a new revision 20 is created but the client does not receive anything around the same time. I have also included the channel assignment output by calling “_user/org1035-user-1” API. The channel “org1035::conv::1” is indeed assigned to this user.

From Sync-Gateway:

2018-10-10T18:05:35.423Z [INF] Sync: [622158d2] Sent all changes to client. User:org1035-user-100
2018-10-10T18:05:35.423Z [DBG] Sync+: [622158d2] Sent all changes to client. User:org1035-user-100
2018-10-10T18:05:35.423Z [DBG] WS+: [622158d2] Sending frame: MSG#1~ (flags= 101000, size= 51)
2018-10-10T18:07:22.663Z [DBG] Import+: Attempting to import doc “org1035::conv::1”…
2018-10-10T18:07:22.665Z [DBG] CRUD+: Doc org1035::conv::1 is not an SG write, based on cas and body hash. cas:155c518decf50000 syncCas:"0x000023b7eb235c15"
2018-10-10T18:07:22.666Z [INF] Import: Created new rev ID 20-13b872567618595326a3ad99aba02da6
2018-10-10T18:07:22.666Z [DBG] CRUD+: Invoking sync on doc “org1035::conv::1” rev 20-13b872567618595326a3ad99aba02da6
2018-10-10T18:07:22.666Z [DBG] CRUD+: No old revision “org1035::conv::1” / “19-0eadd24c115774d96011d776f2936d5f”
2018-10-10T18:07:22.667Z [DBG] CRUD+: No old revision “org1035::conv::1” / “18-8914f63d02f7b58c1601cd101344677a”
2018-10-10T18:07:22.667Z [DBG] CRUD+: No old revision “org1035::conv::1” / “17-51be28367c45170b88c57329c323ed7b”
2018-10-10T18:07:22.667Z [DBG] CRUD+: No old revision “org1035::conv::1” / “16-1a6ee904e190c5faa714a7450c20e800”
2018-10-10T18:07:22.668Z [DBG] CRUD+: No old revision “org1035::conv::1” / “15-dcff1e9b8bdf42a6ca369f3619c867ff”
2018-10-10T18:07:22.668Z [DBG] CRUD+: No old revision “org1035::conv::1” / “14-c348591d862b65f0c360b0e7e7edc5d8”
2018-10-10T18:07:22.668Z [DBG] CRUD+: No old revision “org1035::conv::1” / “13-ae452a0a2c2d2f447cba183dbbfb877c”
2018-10-10T18:07:22.668Z [DBG] CRUD+: No old revision “org1035::conv::1” / “12-96a70c8c8ebc7bbf8bf14c80deb87c4b”
2018-10-10T18:07:22.669Z [DBG] CRUD+: No old revision “org1035::conv::1” / “11-71bfdf4de765410a0bd0e477d1cfe4af”
2018-10-10T18:07:22.669Z [DBG] CRUD+: No old revision “org1035::conv::1” / “10-975608d1d33ea0a3a17c19af30bb2f91”
2018-10-10T18:07:22.669Z [DBG] CRUD+: No old revision “org1035::conv::1” / “9-7a066d338ffc2e6d42681be9c7036958”
2018-10-10T18:07:22.669Z [DBG] CRUD+: No old revision “org1035::conv::1” / “8-6ca6e826dbf40242fdf941688a723562”
2018-10-10T18:07:22.669Z [DBG] CRUD+: No old revision “org1035::conv::1” / “7-47a22e3834c4d470c5eea119b5db5844”
2018-10-10T18:07:22.670Z [DBG] CRUD+: No old revision “org1035::conv::1” / “6-c7ac58b394aad5707e973f44bae22005”
2018-10-10T18:07:22.670Z [DBG] CRUD+: No old revision “org1035::conv::1” / “5-d52adc3405018645ca6187a4e68056f2”
2018-10-10T18:07:22.670Z [DBG] CRUD+: No old revision “org1035::conv::1” / “4-87acdebc302d6e2bb4cafc5b3bea26d8”
2018-10-10T18:07:22.670Z [DBG] CRUD+: No old revision “org1035::conv::1” / “3-d51d4ed8ec8bb272837eb4c8b7b576f9”
2018-10-10T18:07:22.670Z [DBG] CRUD+: No old revision “org1035::conv::1” / “2-3baab0172b1da2534e7e87eb7dca13e1”
2018-10-10T18:07:22.671Z [DBG] CRUD+: No old revision “org1035::conv::1” / “1-2136a63ef1a23cbf025cd5d39ba8f396”
2018-10-10T18:07:22.672Z [DBG] CRUD+: Saving doc (seq: #468, id: org1035::conv::1 rev: 20-13b872567618595326a3ad99aba02da6)
2018-10-10T18:07:22.673Z [INF] CRUD: Stored doc “org1035::conv::1” / “20-13b872567618595326a3ad99aba02da6”
2018-10-10T18:07:22.673Z [DBG] Import+: Imported org1035::conv::1 (delete=false) as rev 20-13b872567618595326a3ad99aba02da6
2018-10-10T18:07:22.678Z [INF] Cache: Received #468 after 6ms (“org1035::conv::1” / “20-13b872567618595326a3ad99aba02da6”)
2018-10-10T18:07:22.678Z [INF] Cache: #468 ==> channel "*"
2018-10-10T18:07:22.678Z [DBG] Changes+: Notifying that “messaging” changed (keys="{*}") count=530

From Client:

2018-10-10 13:05:35.437525-0500 xxxxxx[6264:158521] CouchbaseLite Sync Verbose: {Pull#3} now idle
2018-10-10 13:05:35.437709-0500 xxxxxx[6264:158561] CouchbaseLite Sync Info: {Repl#1} pushStatus=idle, pullStatus=idle, dbStatus=idle, progress=0/0
2018-10-10 13:05:35.437908-0500 xxxxxx[6264:158561] CouchbaseLite Sync Info: {Repl#1} activityLevel=idle: connectionState=2
2018-10-10 13:05:35.438076-0500 xxxxxx[6264:158561] CouchbaseLite Sync Info: {Repl#1} now idle
2018-10-10 13:05:35.438306-0500 xxxxxx[6264:158521] CouchbaseLite Sync Info: CBLReplicator[<*> URL[ws://xxx.xx.xx.xxx:4984/messaging]] is idle, progress 0/0, error: (null)
[13:05:35.439][1][CouchbaseManager.swift][startPushAndPullReplicationForCurrentUser()][313] PushPull Replicator: 0/0, error: nil, activity = idle
2018-10-10 13:05:51.540044-0500 xxxxxx[6264:158559] CouchbaseLite WS Verbose: <CBLWebSocket: 0x6000001625d0>: Checking for timeout in 304.895 sec
2018-10-10 13:05:51.540372-0500 xxxxxx[6264:158559] CouchbaseLite WS Verbose: <CBLWebSocket: 0x6000001625d0>: Checking for timeout in 304.894 sec

!!! NO Data Received here !!!

2018-10-10 13:10:35.368627-0500 xxxxxx[6264:158564] CouchbaseLite WS Info: {C4SocketImpl#1}==> litecore::repl::C4SocketImpl ws://xxx.xx.xx.xxx:4984/messaging/_blipsync
2018-10-10 13:10:35.368931-0500 xxxxxx[6264:158564] CouchbaseLite WS Info: {C4SocketImpl#1} Sending PING
2018-10-10 13:10:35.369176-0500 xxxxxx[6264:158564] CouchbaseLite WS Verbose: >>> sending 6 bytes…
2018-10-10 13:10:35.369541-0500 xxxxxx[6264:161559] CouchbaseLite WS Verbose: (…sent 6 bytes)
2018-10-10 13:10:35.369771-0500 xxxxxx[6264:161559] CouchbaseLite WS Verbose: <CBLWebSocket: 0x6000001625d0>: HasSpaceAvailable
2018-10-10 13:10:35.395068-0500 xxxxxx[6264:161559] CouchbaseLite WS Verbose: <CBLWebSocket: 0x6000001625d0>: HasBytesAvailable

User Channel Assignment:

ubuntu@ip-xxx-xx-xx-xxx:~$ curl -X GET “http://localhost:4985/messaging/_user/org1035-user-100” -H “accept: application/json”

{“name”:“org1035-user-100”,“all_channels”:["!",“org1035::conv::1”,“org1035::conv::123”,“org1035::conv::124”,“org1035::conv::156”,“org1035::conv::18”,“org1035::conv::5”,“org1035::conv::6”,“org1035::conv::7”,“org1035::conv::8”,“org1035::conv::9”]}ubuntu@ip-xxx-xx-xx-xxx:~$


#6

Hm, this is getting beyond me … @adamf? @traun?


#7

From the Sync Gateway logs, I only see the document being added to channel “*” - if the doc was being channeled to channel org1035::conv::1 I’d expect to see a log line like:

2018-10-10T18:07:22.678Z [INF] Cache: #468 ==> channel “org1035::conv::1”

Since that’s not present, I’d guess that your sync function isn’t correctly assigning the document to the channel on this particular document update. Looking at the raw document could confirm that.


#8

Thank you for your response @adamf and @jens.

Below please find the SG configuration file and the raw document and it’s meta data.

Sync Gateway Configuration

{
  "interface":":4984",
  "log": ["*"],
  "logging": {
    "log_file_path": "/var/tmp/sglogs",
    "console": {
      "log_level": "debug",
      "log_keys": ["*"]
    },
    "error": {
      "enabled": true,
      "rotation": {
        "max_size": 20,
        "max_age": 180
      }
    },
    "warn": {
      "enabled": true,
      "rotation": {
        "max_size": 20,
        "max_age": 90
      }
    },
    "info": {
      "enabled": false
    },
    "debug": {
      "enabled": false
    }
  },
  "databases": {
    "messaging": {
          "import_docs": "continuous",
          "bucket":"messaging",
          "server": "http://cb-server:8091",
          "enable_shared_bucket_access":true,
          "import_filter": `
          function(doc) {
              return true;
          }
          `,
          "username": "Administrator",
          "password": "xxxxxxxx",
          "users":{
              "admin": {"password": "password", "admin_channels": ["*"]},
              "demo": {"password": "password"},
              "tester": {"password": "password"}
          },
          "num_index_replicas":0,

          "sync": `
function sync(doc, oldDoc) {
    printDebug('New Doc ID: ' + doc._id);

    if(isRemoved()){
        return;
    }

    // Add participants if this doc is a conversation                                                                                                                                                                                                                    
    if('conversation' == doc.type){
        printDebug('Adding participants to ' + JSON.stringify(doc.channels) + ': ' + JSON.stringify(doc.participants));
        access(doc.participants, doc.channels);
    }

    function isRemoved() {
        return (isDelete() && oldDoc == null);
    }

    function isDelete() {
        return (doc._deleted == true);
    }

    function printDebug(info){
        var d = new Date();
        console.log('[' + d.toTimeString() + '] ' + info);
    }
}
        `

      }
  }
}

Raw Document

{
  "channels": "org1035::conv::1",
  "participants": [
    "org1035-user-0",
    "org1035-user-100"
  ],
  "type": "conversation",
}

Meta Data for DocID: org1035::conv::1

{
  "meta": {
    "id": "org1035::conv::1",
    "rev": "51-155ce031a61c00000000000002000006",
    "expiration": 0,
    "flags": 33554438,
    "type": "json"
  },
  "xattrs": {
    "_sync": {
      "rev": "22-4cf304b4e0029b8e14b23b15f04b6eaf",
      "sequence": 478,
      "recent_sequences": [
        468,
        469,
        478
      ],
      "history": {
        "revs": [
          "4-87acdebc302d6e2bb4cafc5b3bea26d8",
          "8-6ca6e826dbf40242fdf941688a723562",
          "12-96a70c8c8ebc7bbf8bf14c80deb87c4b",
          "21-64b3c122a4050f8da69430af8f64afa9",
          "6-c7ac58b394aad5707e973f44bae22005",
          "7-47a22e3834c4d470c5eea119b5db5844",
          "16-1a6ee904e190c5faa714a7450c20e800",
          "15-dcff1e9b8bdf42a6ca369f3619c867ff",
          "20-13b872567618595326a3ad99aba02da6",
          "5-d52adc3405018645ca6187a4e68056f2",
          "1-2136a63ef1a23cbf025cd5d39ba8f396",
          "19-0eadd24c115774d96011d776f2936d5f",
          "22-4cf304b4e0029b8e14b23b15f04b6eaf",
          "10-975608d1d33ea0a3a17c19af30bb2f91",
          "18-8914f63d02f7b58c1601cd101344677a",
          "2-3baab0172b1da2534e7e87eb7dca13e1",
          "9-7a066d338ffc2e6d42681be9c7036958",
          "13-ae452a0a2c2d2f447cba183dbbfb877c",
          "14-c348591d862b65f0c360b0e7e7edc5d8",
          "11-71bfdf4de765410a0bd0e477d1cfe4af",
          "3-d51d4ed8ec8bb272837eb4c8b7b576f9",
          "17-51be28367c45170b88c57329c323ed7b"
        ],
        "parents": [
          20,
          5,
          19,
          8,
          9,
          4,
          7,
          18,
          11,
          0,
          -1,
          14,
          3,
          16,
          21,
          10,
          1,
          2,
          17,
          13,
          15,
          6
        ],
        "channels": [
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null,
          null
        ]
      },
      "access": {
        "org1035-user-0": {
          "org1035::conv::1": 4
        },
        "org1035-user-100": {
          "org1035::conv::1": 4
        }
      },
      "cas": "0x00001ca631e05c15",
      "value_crc32c": "0xde7bcdc4",
      "time_saved": "2018-10-12T13:41:16.497541622Z"
    }
  }
}

#9

It doesn’t appear that you’re assigning the document to any channels.

Your sync function is making an access call, which will grant users access to the specified channel, but I don’t see anywhere the channel() function is being invoked to actually assign the document itself to a channel.

https://docs.couchbase.com/sync-gateway/2.1/sync-function-api.html#routing


#10

Thank you @adamf for quick response.

To provide you with some background information in what we are trying to do, the documents stored in the bucket were migrated from mysql DB using our migration script and cbimport utility. After the import completes, the migration script creates users using {db}/_users/ API.

As far as assigning documents to channels goes, all the documents contain “channels” property so by calling “/{db}/_resync” Admin API on the imported data, I thought SG should create channel assignments for each document based on the “channels” property in those documents. Also users were assigned to their channels during resync via access() function. Based on the following documentation, I think the documents should have been assigned to channels during the resync.

https://docs.couchbase.com/sync-gateway/2.1/data-routing.html#using-a-channels-property

Please let me know if my understanding is correct above.

DocID: org1035::conv::1

{
  "channels": "org1035::conv::1",
  "participants": [
    "org1035-user-0",
    "org1035-user-100"
  ],
  "type": "conversation",
}

Thank you.


#11

Sync Gateway’s default sync function will automatically assign documents based on a channels property. If you’ve defined a custom sync function, you need to include that explicitly in your sync function.

The linked documentation is intending to describe those as either/or options (“Using a channels property” vs. “Using a sync function”), but I can see how that isn’t clearly stated. I’ll have the documentation updated - thanks for bringing that to my attention.


#12

Thank you. Much appreciated. Actually your documentation is clear. I just forgot reading about it.

Using a sync function


Defining a sync function overrides the default channel mapping mechanism (the document’s channels property is ignored). The default mechanism is equivalent to the following simple sync function:

I will add channel() to my sync function and retry the resync and let you know.

Thank you.


#13

@adamf @jens - thank you. Replication is working as expected now.