Forcing sync of iOS CBL document to Sync Gateway?

The problem I am trying to solve is the documents not syncing immediately.

What is happening: I modified a document and saved it to Couchbase using database.saveDocument(mutableDoc). I would expect the change to be propagated almost instantly to the Sync Gateway, but it is not being propagated. I confirm that the modified document is not live because I do a GET of the Document via the Sync Gateway REST API.

I have noticed that the only way to “force” instant propagation is to move the app to the background in iOS (suspend?) and then move it back as the active app. Then I check the document via the REST API and the changes are there.

I would like to know if there’s any reason why this is happening (default behaviour? misconfiguration?) so that I can fix it, and/or also if there is a way to trigger the update of the SG manually; to force the document’s propagation from CBL to the SG.

Thanks for reading!

Can you enable the logs and see, whether the replicator is busy or idle during the saving?

Also, which version of CouchbaseLite you are using?

Let me share with you the “timeline” of the logs. Logs are mainly through the ReplicatorListener and a Document change listener:

  1. Document’s revision is rev: 98. (Checked via SG REST API).

  2. I edit a field (last_name) of the document. The document change listener notices this change and outputs:

Refreshing ID: users::182
  1. Document from REST API still says rev: 98.

  2. Move the app to the background (via iOS task manager). Output from Replicator:

2019-10-01 12:28:35.206622-0500 Register[22266:333429] [Snapshotting] Snapshotting a view (0x7fdd03053400, UIKeyboardImpl) that is not in a visible window requires afterScreenUpdates:YES.
Busy transferring data
All documents synced
Busy transferring data
All documents synced
Replicator in offline state
All documents synced
Replicator in offline state
All documents synced
Connecting to Sync Gateway
All documents synced
Connecting to Sync Gateway
All documents synced
  1. Document from REST API says it’s still in rev: 98.

  2. Move app again to main view from background. Output from Replicator:

2019-10-01 12:29:02.900973-0500 Register[22266:336140] TIC Read Status [2:0x0]: 1:57
Busy transferring data
All documents synced
Busy transferring data
All documents synced
Busy transferring data
Documents 1632 still pending sync
Replicator in Idle state
All documents synced
Busy transferring data
All documents synced
Replicator in Idle state
All documents synced
  1. Document from REST API updated to rev: 99 and contains the changes.

Can you use this documentation and enable the logging

Database.log.console.level = .verbose

  1. Current rev: 99. Then updated document:
2019-10-01 12:56:29.264054-0500 Register[22626:347918] CouchbaseLite Database Verbose: {DB#17}==> litecore::SQLiteDataFile /Users/alexmachina/Library/Developer/CoreSimulator/Devices/CA75A776-8EA8-443A-98AC-08F9E7528E26/data/Containers/Data/Application/7B11ED0E-5C3A-4DBE-8E75-05CAD58B02FD/Library/Application Support/CouchbaseLite/user.cblite2/db.sqlite3 @0x600000e4cd20
2019-10-01 12:56:29.264219-0500 Register[22626:347918] CouchbaseLite Database Verbose: {DB#17} begin transaction
2019-10-01 12:56:29.266528-0500 Register[22626:347918] CouchbaseLite Database Verbose: {DB#17} Saved 'users::182' rev #100-75493e3e0aadd055d99491e4c8bf64ff43272eb8 as seq 4
2019-10-01 12:56:29.266766-0500 Register[22626:347918] CouchbaseLite Database Verbose: {DB#17} commit transaction
Refreshing ID: users::182
  1. Rev: 99. Moved app to background:
2019-10-01 12:58:04.452205-0500 Register[22626:347918] CouchbaseLite Replicator Info: CBLReplicator[<*> URL[ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/users/]]: App backgrounding, not active, suspending the replicator
2019-10-01 12:58:04.452458-0500 Register[22626:347918] CouchbaseLite Replicator Info: CBLReplicator[<*> URL[ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/users/]]: Set suspended = 1 (state = 5, status = 3)
2019-10-01 12:58:04.458058-0500 Register[22626:347918] CouchbaseLite Replicator Info: CBLReplicator[<*> URL[ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/properties/]]: App backgrounding, not active, suspending the replicator
2019-10-01 12:58:04.458702-0500 Register[22626:347918] CouchbaseLite Replicator Info: CBLReplicator[<*> URL[ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/properties/]]: Set suspended = 1 (state = 5, status = 3)
2019-10-01 12:58:04.490328-0500 Register[22626:349121] CouchbaseLite Replicator Info: {Repl#3} Told to stop!
2019-10-01 12:58:04.491446-0500 Register[22626:349121] CouchbaseLite Network Info: {Connection#2} Closing with code 1000, msg ''
2019-10-01 12:58:04.493183-0500 Register[22626:349290] CouchbaseLite Replicator Info: {Repl#8} Told to stop!
2019-10-01 12:58:04.494218-0500 Register[22626:349290] CouchbaseLite Network Info: {Connection#7} Closing with code 1000, msg ''
2019-10-01 12:58:04.497834-0500 Register[22626:349282] CouchbaseLite Network Info: {C4SocketImpl#18}==> litecore::repl::C4SocketImpl ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/users/_blipsync @0x7fbb09e2a830
2019-10-01 12:58:04.498472-0500 Register[22626:349282] CouchbaseLite Network Info: {C4SocketImpl#18} Requesting close with status=1000, message=''
2019-10-01 12:58:04.499518-0500 Register[22626:349282] CouchbaseLite Network Verbose: >>> sending 8 bytes...
2019-10-01 12:58:04.499618-0500 Register[22626:349290] CouchbaseLite Replicator Info: {Repl#8} activityLevel=busy: connectionState=3
2019-10-01 12:58:04.500466-0500 Register[22626:349290] CouchbaseLite Replicator Info: {Repl#8} now busy
2019-10-01 12:58:04.501274-0500 Register[22626:349290] CouchbaseLite Replicator Info: CBLReplicator[<*> URL[ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/properties/]] is busy, progress 0/0, error: (null)
2019-10-01 12:58:04.501836-0500 Register[22626:348090] CouchbaseLite Network Info: {C4SocketImpl#19}==> litecore::repl::C4SocketImpl ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/properties/_blipsync @0x7fbb09c45580
2019-10-01 12:58:04.502420-0500 Register[22626:349121] CouchbaseLite Replicator Info: {Repl#3} activityLevel=busy: connectionState=3
2019-10-01 12:58:04.503172-0500 Register[22626:349121] CouchbaseLite Replicator Info: {Repl#3} now busy
2019-10-01 12:58:04.503725-0500 Register[22626:348090] CouchbaseLite Network Info: {C4SocketImpl#19} Requesting close with status=1000, message=''
2019-10-01 12:58:04.504142-0500 Register[22626:349282] CouchbaseLite Network Verbose:     (...sent 8 bytes)
2019-10-01 12:58:04.504085-0500 Register[22626:348090] CouchbaseLite Network Verbose: >>> sending 8 bytes...
2019-10-01 12:58:04.504658-0500 Register[22626:349121] CouchbaseLite Replicator Info: CBLReplicator[<*> URL[ws://ec2-13-56-209-220.us-west-1.compute.amazonaws.com:4984/users/]] is busy, progress 0/0, error: (null)
2019-10-01 12:58:04.506402-0500 Register[22626:348090] CouchbaseLite Network Verbose:     (...sent 8 bytes)
2019-10-01 12:58:04.509785-0500 Register[22626:349282] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000655b80>: HasSpaceAvailable
2019-10-01 12:58:04.511133-0500 Register[22626:348090] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000653ca0>: HasSpaceAvailable
2019-10-01 12:58:04.586328-0500 Register[22626:349282] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000655b80>: HasBytesAvailable
2019-10-01 12:58:04.586399-0500 Register[22626:348090] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000653ca0>: HasBytesAvailable
2019-10-01 12:58:04.588357-0500 Register[22626:349282] CouchbaseLite Network Verbose: DoRead...
2019-10-01 12:58:04.590041-0500 Register[22626:348090] CouchbaseLite Network Verbose: DoRead...
2019-10-01 12:58:04.594484-0500 Register[22626:349282] CouchbaseLite Network Verbose: DoRead read 4 bytes
2019-10-01 12:58:04.596375-0500 Register[22626:348090] CouchbaseLite Network Verbose: DoRead read 4 bytes
2019-10-01 12:58:04.596956-0500 Register[22626:349282] CouchbaseLite Network Verbose: <<< received 4 bytes [now 4 pending]
2019-10-01 12:58:04.598437-0500 Register[22626:348090] CouchbaseLite Network Verbose: <<< received 4 bytes [now 4 pending]
2019-10-01 12:58:04.600303-0500 Register[22626:349282] CouchbaseLite Network Info: {C4SocketImpl#18} Close confirmed by peer; disconnecting socket now
2019-10-01 12:58:04.601996-0500 Register[22626:349282] CouchbaseLite Network Info: CBLWebSocket closeSocket requested
2019-10-01 12:58:04.602046-0500 Register[22626:348090] CouchbaseLite Network Info: {C4SocketImpl#19} Close confirmed by peer; disconnecting socket now
2019-10-01 12:58:04.604229-0500 Register[22626:348090] CouchbaseLite Network Info: CBLWebSocket closeSocket requested
2019-10-01 12:58:04.604781-0500 Register[22626:349282] CouchbaseLite Network Verbose: DoRead read 0 bytes
2019-10-01 12:58:04.606500-0500 Register[22626:348090] CouchbaseLite Network Verbose: DoRead read 0 bytes
2019-10-01 12:58:04.607611-0500 Register[22626:349282] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000655b80>: EndEncountered on read stream
2019-10-01 12:58:04.608371-0500 Register[22626:348090] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000653ca0>: EndEncountered on read stream
2019-10-01 12:58:04.609635-0500 Register[22626:348090] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000653ca0>: Disconnect
2019-10-01 12:58:04.613976-0500 Register[22626:347918] [Snapshotting] Snapshotting a view (0x7fbb0a1e7800, UIKeyboardImpl) that is not in a visible window requires afterScreenUpdates:YES.
2019-10-01 12:58:04.610483-0500 Register[22626:349282] CouchbaseLite Network Verbose: <CBLWebSocket: 0x600000655b80>: Disconnect
2019-10-01 12:58:04.628168-0500 Register[22626:349282] CouchbaseLite Network Info: CBLWebSocket CLOSED
2019-10-01 12:58:04.628251-0500 Register[22626:348090] CouchbaseLite Network Info: CBLWebSocket CLOSED
2019-10-01 12:58:04.630297-0500 Register[22626:349282] CouchbaseLite Network Info: {C4SocketImpl#18} Socket disconnected cleanly
2019-10-01 12:58:04.635347-0500 Register[22626:349282] CouchbaseLite Network Info: {C4SocketImpl#18} sent 239 bytes, rcvd 119, in 143.483 sec (2/sec, 1/sec)
2019-10-01 12:58:04.641449-0500 Register[22626:349282] CouchbaseLite Network Verbose: C4Socket of <CBLWebSocket: 0x600000655b80> is being disposed
2019-10-01 12:58:04.643045-0500 Register[22626:348090] CouchbaseLite Network Info: {C4SocketImpl#19} Socket disconnected cleanly
2019-10-01 12:58:04.645382-0500 Register[22626:348090] CouchbaseLite Network Info: {C4SocketImpl#19} sent 270 bytes, rcvd 120, in 143.405 sec (2/sec, 1/sec)
2019-10-01 12:58:04.648253-0500 Register[22626:348090] CouchbaseLite Network Verbose: C4Socket of <CBLWebSocket: 0x600000653ca0> is being disposed
2019-10-01 12:58:04.648486-0500 Register[22626:349282] CouchbaseLite Network Verbose: DEALLOC <CBLWebSocket: 0x600000655b80>
2019-10-01 12:58:04.649199-0500 Register[22626:348090] CouchbaseLite Network Verbose: DEALLOC <CBLWebSocket: 0x600000653ca0>
2019-10-01 12:58:04.649680-0500 Register[22626:349282] CouchbaseLite Network Info: {Connection#2} Closed with WebSocket status 1000:
2019-10-01 12:58:04.650429-0500 Register[22626:349282] CouchbaseLite Replicator Info: {Repl#3} Connection closed with WebSocket status 1000: "" (state=3)
2019-10-01 12:58:04.651050-0500 Register[22626:349282] CouchbaseLite Replicator Info: {Repl#3} activityLevel=stopped: connectionState=0
2019-10-01 12:58:04.651207-0500 Register[22626:349282] CouchbaseLite Replicator Info: {Repl#3} now stopped
Busy transferring data
All documents synced
Busy transferring data
All documents synced

Rest of the logs was too long for the forum haha. Here is a gist with the output when bringing the app to the foreground:

This logs doesn’t help understand what happens with the replicator syncing, when you save the document. Wondering whether the replicator is busy/idle/stopped during document saving. If we could, check the logs whats the status of replicator when you are saving document, that will help understand the issue more clearly.

Could you please start collecting the logs, before the document is saving. Stop collecting it when replicator is idle/stopped.

I don’t know if I am doing it correctly… but this is the output:

2019-10-01 17:50:56.652972-0500 Register[30558:469480] CouchbaseLite Database Verbose: {DB#1} begin transaction
2019-10-01 17:50:56.653530-0500 Register[30558:469480] CouchbaseLite Database Verbose: {DB#1} Saved 'users::182' rev #108-d83200880aaa151b878b0c898f0eaf08b4195df1 as seq 34
2019-10-01 17:50:56.653763-0500 Register[30558:469480] CouchbaseLite Database Verbose: {DB#1} commit transaction
Refreshing ID: users::182

does this mean, there is no replicator logs when saving the data? did you start replicator before saving?

if you have started, then it should show some logs( with CouchbaseLite Replicator) which should be shown together with the database logs.

The replicator in theory is starting before and should be running for the whole duration of the app’s lifecycle.

I have this function set up for listening to replicator changes, but it doesn’t get triggered when I update the document. It only gets triggered when I move the app to the background (and foreground).

    private func replicatorStatusListener(change: ReplicatorChange) {
        let s = change.status
        switch s.activity {
        case .busy:
            print("Busy transferring data")
        case .connecting:
            print("Connecting to Sync Gateway")
        case .idle:
            print("Replicator in Idle state")
        case .offline:
            print("Replicator in offline state")
        case .stopped:
            print("Completed syncing documents")
        }
        
        // Workarond for BUG :https://github.com/couchbase/couchbase-lite-ios/issues/1816.
        if s.progress.completed == s.progress.total {
            print("All documents synced")
        }
        else {
            print("Documents \(s.progress.total - s.progress.completed) still pending sync")
        }
    }

Can you force the replicator start(may be from AppDelegate) before saving and see, whether it is replicating or not.

What I did was made a sample project with the minimal replication functions (get from Database and save and then perform an action with a document change listener) and it was working there.

I think it may have something to do with my replicator because I do not get any output from the Replicator (as if it was turned off). Do you know if there is a guide for best practices for a project with Couchbase Lite?

Some useful URLs

1 Like

I ended up looking through the documentation and rewrote the code from scratch basing myself off of this example and now it works.

In terms of what was wrong, I narrowed it down to the Replicator being stopped somewhere, but never figured out where. at least if it happens again I have a better idea after rewriting the code myself.

Thanks for the guidance @jayahari.vavachan and for working on that sample code that worked for me!

1 Like