Replicator in Android get stuck at busy state when it goes back to online from offline

No, there’s no public API to change the WebSocket heartbeat interval. What’s your rationale for needing to change it?

When the Couchbase lite replicator stuck in busy state, I found that after 5 minutes, with a message “connection reset by pair”, the replicator reconnects sync gateway, and it goes through offline->connecting->idle. And this behavior is what I am expected. I think this is caused by heartbeat timeout. However the waiting time is a little be long for me. I am thinking if it is possible to modify the heartbeat interval to a shorter time so that replicator could react quicker to internet reconnection.

after 5 minutes, with a message “connection reset by pair”, the replicator reconnects

“Connection reset by peer” means that the server disconnected. That probably means Sync Gateway detected it wasn’t getting any traffic from CBL, i.e. it’s SG’s heartbeat, not CBL’s. Have you checked your CBL logs at the time of the disconnect to see what happened?

I’m curious why CBL isn’t sending heartbeat messages, or why SG isn’t receiving them. I see above that I pointed out a possible network error at the Java level that may not be getting through to the core replicator. So it may be that data can’t be sent for some reason but the replicator doesn’t know it.

That message from C4Socket is not really a warning. It simply means that core is informing the java layer that the socket object @4089772456 has succeeded in writing 236 bytes to the wire.

Very little of this log is generated by the java layer. I’m not sure I can add anything. It looks like the replicator is legit busy and that it is awaiting one more byte (progress 3351/3352). No idea what that byte could be…

Something might be wrong on the Sync Gateway side. Looking at the logs again, the last thing that happens is that CBL requests a document from SG, and the request gets written to the socket, but then it never receives any response. So I wonder what’s happening on the server side.

Similar situation is happening, also total documents number on the replicator keeps increasing and completed count remains at 0. Appreciate any clues in resolving this,

    2019-10-25 10:41:08.563 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.606 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.607 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.610 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.610 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.651 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.652 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.654 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.655 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.693 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.693 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.695 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.696 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.734 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.734 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.737 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.737 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.774 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.775 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.777 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.778 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.816 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.817 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.819 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.820 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.866 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.866 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.869 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.870 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.908 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.908 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.911 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.911 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:08.956 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.956 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:08.959 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:08.959 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.008 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.008 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.011 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.011 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.048 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.049 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.051 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.051 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.089 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.089 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.092 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.092 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.131 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.131 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.134 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.134 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.180 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.180 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.183 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.183 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.229 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.229 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.232 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.232 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.275 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.276 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.278 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.278 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.315 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.316 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.318 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.318 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.357 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.358 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.360 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.360 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.400 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.401 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.403 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.403 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.447 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.448 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.450 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.450 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.494 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.496 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.497 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.498 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.539 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.539 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.541 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.542 15880-15911/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.579 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.580 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.583 15880-15912/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536
2019-10-25 10:41:09.583 15880-15912/com.couchbaselitetest.android W/C4Socket: completedWrite(long) handle -> 2000874536, byteCount -> 11
2019-10-25 10:41:09.622 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.623 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.completedReceive() handle -> 2000874536
2019-10-25 10:41:09.625 15880-15911/com.couchbaselitetest.android W/C4Socket: C4Socket.write() handle -> 2000874536

@fatmonkey45, you’ll need to turn on more logging. What’s there is just showing byte counts going through the socket, which isn’t useful for diagnosing this kind of thing.

Database.setLevel(DomainLevel.ALL, LogLevel.Verbose) produces no changes in logs

That method is deprecated and does not function correctly anymore unfortunately. We are trying to make it function in at least a semi-usable way for the next release, but you should use the new logging API indicated in the link.

Got the Verbose logs out. Replaced bytes with …
This is happening every minute or so and goes on for a while. Here is a snippet from logs:

    /COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2815 M--C, length  8130
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2815 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2815 ---C, length   469
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2815 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2815 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2815
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1518255'..'1518454')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2815 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2815 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2815 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2815 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2816 M--C, length  8117
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2816 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2816 ---C, length   469
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2816 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2816 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2816
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1518455'..'1518654')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2816 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2816 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2816 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2816 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2817 M--C, length  8131
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2817 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2817 ---C, length   471
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2817 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2817 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2817
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1518655'..'1518854')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2817 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2817 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2817 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2817 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2818 M--C, length  8137
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2818 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2818 ---C, length   469
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2818 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2818 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2818
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1518855'..'1519054')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2818 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2818 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2818 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2818 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2819 M--C, length  8124
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2819 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2819 ---C, length   472
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2819 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2819 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2819
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1519055'..'1519254')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2819 w/request for 0 revs
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2819 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2819 ---C, bytes 0--7
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2819 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2820 M--C, length  8141
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2820 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2820 ---C, length   468
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2820 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2820 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2820
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1519255'..'1519454')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2820 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2820 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2820 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2820 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2821 M--C, length  8132
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2821 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2821 ---C, length   470
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2821 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2821 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2821
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1519455'..'1519654')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2821 w/request for 0 revs
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2821 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2821 ---C, bytes 0--7
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2821 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2822 M--C, length  8135
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2822 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2822 ---C, length   467
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2822 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2822 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2822
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1519655'..'1519854')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2822 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2822 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2822 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2822 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2823 M--C, length  8195
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2823 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2823 ---C, length  1130
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2823 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2823 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2823
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1519855'..'1520094')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2823 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2823 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2823 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2823 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2824 M--C, length  8209
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2824 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2824 ---C, length  1275
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2824 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2824 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2824
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1520096'..'1520379')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2824 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2824 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2824 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2824 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2825 M--C, length  8207
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2825 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2825 ---C, length  1256
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2825 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2825 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2825
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 200 changes (seq '1520380'..'1520614')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2825 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2825 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2825 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2825 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2826 ---C, length  3020
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2826 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2826 Z
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2826 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2826
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Received 63 changes (seq '1520615'..'1520700')
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} Responded to 'changes' REQ#2826 w/request for 0 revs
/COUCHBASELOGGER: INFO:REPLICATOR: {DBWorker#49} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Sending RES #2826 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50}     Sending frame: RES #2826 ---C, bytes 0--7
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Now waiting for 0 'rev' messages; 2573 known sequences pending
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Finished sending RES #2826 Z
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} ...Wrote 11 bytes to WebSocket (writeable=1)
/COUCHBASELOGGER: VERBOSE:NETWORK: WebSocketListener.onMessage() bytes -> ...
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip6BLIPIOE#50} Received frame: REQ #2827 --NC, length    13
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Receiving 'changes' REQ #2827 NZ
/COUCHBASELOGGER: VERBOSE:NETWORK: {N8litecore4blip10ConnectionE#47} Finished receiving 'changes' REQ #2827 NZ
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Received 'changes' REQ#2827 (0 queued; 0 revs pending, 0 active)
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} Handling 'changes' REQ#2827
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} Caught up with remote changes
/COUCHBASELOGGER: INFO:REPLICATOR: {Pull#51} activityLevel=idle: pendingResponseCount=0, _caughtUp=1, _waitingForChangesCallback=0, _pendingRevMessages=0, _activeIncomingRevs=0
/COUCHBASELOGGER: VERBOSE:REPLICATOR: {Pull#51} now idle
bStatus=idle, progress=0/2573
/COUCHBASELOGGER: INFO:REPLICATOR: {Repl#48} activityLevel=idle: connectionState=2
/COUCHBASELOGGER: INFO:REPLICATOR: {Repl#48} now idle
/COUCHBASELOGGER: INFO:REPLICATOR: C4ReplicatorListener.statusChanged() status -> ...
atabase@5dcd966{name='bucket_qa'} URLEndpoint{url=wss://sq.qa.someendpoint.nz/bucket_qa}]: status changed: C4ReplicatorStatus{activityLevel=3, progressUnitsCompleted=0, progressUnitsTotal=2573, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
atabase@5dcd966{name='bucket_qa'} URLEndpoint{url=wss://sq.qa.someendpoint.nz/bucket_qa}] is idle, progress 0/2573, error: null

Hello @jens here is another log when replicator stuck at busy state. I don’t know if we could discover anything new from it:
V/CouchbaseLite/NETWORK( 5944): WebSocketListener.onMessage() bytes -> 020894cbd10903210c06e05df27c85fc5caf515711113546fad280edfe74861be0bb4972065f72d0f6eebfaabeea77573033521afeb1f7a2834ec1a3415abcb83d8798863e052fd808a769544c132ae50f55a11684

V/CouchbaseLite/NETWORK( 5944): {N8litecore4repl12C4SocketImplE#28} Received 85-byte message

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip6BLIPIOE#29} Received frame: REQ #2 ---C, length 83

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip10ConnectionE#26} Receiving 'changes' REQ #2 Z

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip10ConnectionE#26} Finished receiving 'changes' REQ #2 Z

V/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} Received 'changes' REQ#2 (0 queued; 0 revs pending, 0 active, 0 unfinished)

V/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} Handling 'changes' REQ#2

I/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} activityLevel=busy: pendingResponseCount=0, _caughtUp=1, _pendingRevMessages=0, _activeIncomingRevs=0

V/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} now busy

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} pushStatus=idle, pullStatus=busy, progress=0/0

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} activityLevel=busy: connectionState=2

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} now busy

I/CouchbaseLite/REPLICATOR( 5944): C4ReplicatorListener.statusChanged, context: Replicator{@1ff1a270,<*>,Database{@167dea04, name='demo'},URLEndpoint{url=wss://config.test.com/channel/demo}], status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}

I/CouchbaseLite/REPLICATOR( 5944): Replicator{@1ff1a270,<*>,Database{@167dea04, name='demo'},URLEndpoint{url=wss://config.test.com/channel/demo}]: status changed: (0, 0) @C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=0, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}

I/CouchbaseLite/REPLICATOR( 5944): Replicator{@1ff1a270,<*>,Database{@167dea04, name='demo'},URLEndpoint{url=wss://config.test.com/channel/demo}] is busy, progress 0/0, error: null

I/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl9RevFinderE#32}==> N8litecore4repl9RevFinderE ->wss://config.test.com/channel/demo/_blipsync @0xd647dec0

I/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl9RevFinderE#32} Received 1 changes (seq '1057'..'1057')

I/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl9RevFinderE#32} Responded to 'changes' REQ#2 w/request for 1 revs

V/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl9RevFinderE#32} now idle

V/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} Now waiting for 1 'rev' messages; 1 known sequences pending

V/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} progress +0/+1, 0 docs -- now 0 / 1, 0 docs

I/CouchbaseLite/REPLICATOR( 5944): {N8litecore4repl6PullerE#31} activityLevel=busy: pendingResponseCount=0, _caughtUp=1, _pendingRevMessages=1, _activeIncomingRevs=0

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} pushStatus=idle, pullStatus=busy, progress=0/0

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} activityLevel=busy: connectionState=2

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} pushStatus=idle, pullStatus=busy, progress=0/1

V/CouchbaseLite/REPLICATOR( 5944): {Repl#27} progress +0/+1, 0 docs -- now 0 / 1, 0 docs

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} activityLevel=busy: connectionState=2

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip6BLIPIOE#29} Sending RES #2 Z

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip6BLIPIOE#29} Sending frame: RES #2 ---C, bytes 0--320

V/CouchbaseLite/NETWORK( 5944): {N8litecore4repl12C4SocketImplE#28} Sending 323-byte message

V/CouchbaseManager$Abstra( 5944): Replicator busy

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip6BLIPIOE#29} Finished sending RES #2 Z

V/CouchbaseLite/NETWORK( 5944): {N8litecore4blip6BLIPIOE#29} ...Wrote 323 bytes to WebSocket (writeable=1)

I/CouchbaseLite/REPLICATOR( 5944): C4ReplicatorListener.statusChanged, context: Replicator{@1ff1a270,<*>,Database{@167dea04, name='demo'},URLEndpoint{url=wss://config.test.com/channel/demo}], status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=1, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}

I/CouchbaseLite/REPLICATOR( 5944): {Repl#27} activityLevel=busy: connectionState=2

I/CouchbaseLite/REPLICATOR( 5944): Replicator{@1ff1a270,<*>,Database{@167dea04, name='demo'},URLEndpoint{url=wss://config.test.com/channel/demo}]: status changed: (0, 0) @C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=1, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}

I/CouchbaseLite/REPLICATOR( 5944): Replicator{@1ff1a270,<*>,Database{@167dea04, name='demo'},URLEndpoint{url=wss://config.test.com/channel/demo}] is busy, progress 0/1, error: null

V/CouchbaseManager$Abstra( 5944): Replicator busy

@humpback_whale : This seems like the same situation as before: CBL is requesting a document revision from the server, but never receives a response.

@jens Thanks! So is there any way we can get it sorted? Is there a recommended network configuration for the sync gateway server? Or a recommended network configuration between SG and Couchbase ?

Is there something specific we can look for to determine why no response is received?

I’d like to chime in that I ran into the same or at least very similar issue.

Setup:

CBL 2.7 SNAPSHOT (from around 2019-10-31)
SG 2.6
nginx as loadbalancer

CBL logs

2019-11-08 11:10:47.103 I/CouchbaseLite/QUERY: {Query#194}==> N8litecore11SQLiteQueryE 0x7813cf71b0 @0x7813cf71b0
2019-11-08 11:10:47.103 I/QUERY: {Query#194}==> N8litecore11SQLiteQueryE 0x7813cf71b0 @0x7813cf71b0
2019-11-08 11:10:47.103 I/CouchbaseLite/QUERY: {Query#194} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["AND",["=",[".type"],"shoppingListItem"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]],["=",[".shoppingListId"],"2wa55i76i46o"]]}
2019-11-08 11:10:47.103 I/QUERY: {Query#194} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["AND",["=",[".type"],"shoppingListItem"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]],["=",[".shoppingListId"],"2wa55i76i46o"]]}
2019-11-08 11:10:47.104 I/CouchbaseLite/QUERY: {Query#194} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE ((fl_value(_doc.body, 'type') = 'shoppingListItem' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND fl_value(_doc.body, 'shoppingListId') = '2wa55i76i46o') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.104 I/QUERY: {Query#194} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE ((fl_value(_doc.body, 'type') = 'shoppingListItem' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND fl_value(_doc.body, 'shoppingListId') = '2wa55i76i46o') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.106 I/CouchbaseLite/QUERY: {QueryEnum#195}==> N8litecore21SQLiteQueryEnumeratorE 0x7813c85368 @0x7813c85368
2019-11-08 11:10:47.106 I/QUERY: {QueryEnum#195}==> N8litecore21SQLiteQueryEnumeratorE 0x7813c85368 @0x7813c85368
2019-11-08 11:10:47.106 I/CouchbaseLite/QUERY: {QueryEnum#195} Created on {Query#194} with 1 rows (326 bytes) in 0.977ms
2019-11-08 11:10:47.106 I/QUERY: {QueryEnum#195} Created on {Query#194} with 1 rows (326 bytes) in 0.977ms
2019-11-08 11:10:47.107 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.107 I/QUERY: End of query enumeration
2019-11-08 11:10:47.119 I/CouchbaseLite/QUERY: {Query#196}==> N8litecore11SQLiteQueryE 0x7813cf73f0 @0x7813cf73f0
2019-11-08 11:10:47.119 I/QUERY: {Query#196}==> N8litecore11SQLiteQueryE 0x7813cf73f0 @0x7813cf73f0
2019-11-08 11:10:47.119 I/CouchbaseLite/QUERY: {Query#196} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["=",[".type"],"shop"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]]}
2019-11-08 11:10:47.119 I/QUERY: {Query#196} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["=",[".type"],"shop"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]]}
2019-11-08 11:10:47.119 I/CouchbaseLite/QUERY: {Query#196} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE (fl_value(_doc.body, 'type') = 'shop' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.119 I/QUERY: {Query#196} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE (fl_value(_doc.body, 'type') = 'shop' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.121 I/CouchbaseLite/QUERY: {QueryEnum#197}==> N8litecore21SQLiteQueryEnumeratorE 0x7813c89788 @0x7813c89788
2019-11-08 11:10:47.121 I/QUERY: {QueryEnum#197}==> N8litecore21SQLiteQueryEnumeratorE 0x7813c89788 @0x7813c89788
2019-11-08 11:10:47.121 I/CouchbaseLite/QUERY: {QueryEnum#197} Created on {Query#196} with 2 rows (436 bytes) in 0.225ms
2019-11-08 11:10:47.121 I/QUERY: {QueryEnum#197} Created on {Query#196} with 2 rows (436 bytes) in 0.225ms
2019-11-08 11:10:47.122 I/FirebasePerformance: Session ID - fccc628cd2e04d33a6919f851cc3b4ac
2019-11-08 11:10:47.122 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.122 I/QUERY: End of query enumeration
2019-11-08 11:10:47.148 I/CouchbaseLite/QUERY: {QueryEnum#198}==> N8litecore21SQLiteQueryEnumeratorE 0x781704d608 @0x781704d608
2019-11-08 11:10:47.148 I/QUERY: {QueryEnum#198}==> N8litecore21SQLiteQueryEnumeratorE 0x781704d608 @0x781704d608
2019-11-08 11:10:47.148 I/CouchbaseLite/QUERY: {QueryEnum#198} Created on {Query#26} with 1 rows (326 bytes) in 0.154ms
2019-11-08 11:10:47.148 I/QUERY: {QueryEnum#198} Created on {Query#26} with 1 rows (326 bytes) in 0.154ms
2019-11-08 11:10:47.148 I/CouchbaseLite/QUERY: LiveQuery refresh: null > com.couchbase.lite.ResultSet@d5f5ae0
2019-11-08 11:10:47.148 I/QUERY: LiveQuery refresh: null > com.couchbase.lite.ResultSet@d5f5ae0
2019-11-08 11:10:47.167 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.167 I/QUERY: End of query enumeration
2019-11-08 11:10:47.183 I/CouchbaseLite/QUERY: {Query#199}==> N8litecore11SQLiteQueryE 0x7813cf74b0 @0x7813cf74b0
2019-11-08 11:10:47.183 I/QUERY: {Query#199}==> N8litecore11SQLiteQueryE 0x7813cf74b0 @0x7813cf74b0
2019-11-08 11:10:47.183 I/CouchbaseLite/QUERY: {Query#199} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["AND",["=",[".type"],"price"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]],["=",[".item.id"],"92446c031dbe"]]}
2019-11-08 11:10:47.183 I/QUERY: {Query#199} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["AND",["=",[".type"],"price"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]],["=",[".item.id"],"92446c031dbe"]]}
2019-11-08 11:10:47.183 I/CouchbaseLite/QUERY: {Query#199} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE ((fl_value(_doc.body, 'type') = 'price' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND fl_value(_doc.body, 'item.id') = '92446c031dbe') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.183 I/QUERY: {Query#199} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE ((fl_value(_doc.body, 'type') = 'price' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND fl_value(_doc.body, 'item.id') = '92446c031dbe') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.184 I/CouchbaseLite/QUERY: {QueryEnum#200}==> N8litecore21SQLiteQueryEnumeratorE 0x7813d60188 @0x7813d60188
2019-11-08 11:10:47.184 I/QUERY: {QueryEnum#200}==> N8litecore21SQLiteQueryEnumeratorE 0x7813d60188 @0x7813d60188
2019-11-08 11:10:47.184 I/CouchbaseLite/QUERY: {QueryEnum#200} Created on {Query#199} with 0 rows (2 bytes) in 0.134ms
2019-11-08 11:10:47.184 I/QUERY: {QueryEnum#200} Created on {Query#199} with 0 rows (2 bytes) in 0.134ms
2019-11-08 11:10:47.184 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.184 I/QUERY: End of query enumeration
2019-11-08 11:10:47.186 I/CouchbaseLite/QUERY: {Query#201}==> N8litecore11SQLiteQueryE 0x7813cf76f0 @0x7813cf76f0
2019-11-08 11:10:47.187 I/QUERY: {Query#201}==> N8litecore11SQLiteQueryE 0x7813cf76f0 @0x7813cf76f0
2019-11-08 11:10:47.187 I/CouchbaseLite/QUERY: {Query#201} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["=",[".type"],"shop"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]]}
2019-11-08 11:10:47.187 I/QUERY: {Query#201} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["=",[".type"],"shop"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]]}
2019-11-08 11:10:47.187 I/CouchbaseLite/QUERY: {Query#201} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE (fl_value(_doc.body, 'type') = 'shop' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.187 I/QUERY: {Query#201} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE (fl_value(_doc.body, 'type') = 'shop' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.187 I/CouchbaseLite/QUERY: {QueryEnum#202}==> N8litecore21SQLiteQueryEnumeratorE 0x7813d60368 @0x7813d60368
2019-11-08 11:10:47.187 I/QUERY: {QueryEnum#202}==> N8litecore21SQLiteQueryEnumeratorE 0x7813d60368 @0x7813d60368
2019-11-08 11:10:47.187 I/CouchbaseLite/QUERY: {QueryEnum#202} Created on {Query#201} with 2 rows (436 bytes) in 0.133ms
2019-11-08 11:10:47.187 I/QUERY: {QueryEnum#202} Created on {Query#201} with 2 rows (436 bytes) in 0.133ms
2019-11-08 11:10:47.188 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.188 I/QUERY: End of query enumeration
2019-11-08 11:10:47.194 I/CouchbaseLite/QUERY: {Query#203}==> N8litecore11SQLiteQueryE 0x7813cf77b0 @0x7813cf77b0
2019-11-08 11:10:47.194 I/QUERY: {Query#203}==> N8litecore11SQLiteQueryE 0x7813cf77b0 @0x7813cf77b0
2019-11-08 11:10:47.194 I/CouchbaseLite/QUERY: {Query#203} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["AND",["=",[".type"],"price"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]],["=",[".item.id"],"f1ed22fa28ce"]]}
2019-11-08 11:10:47.194 I/QUERY: {Query#203} Compiling JSON query: {"WHAT":[["."],["._id"]],"WHERE":["AND",["AND",["=",[".type"],"price"],["=",[".channels"],"7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n"]],["=",[".item.id"],"f1ed22fa28ce"]]}
2019-11-08 11:10:47.194 I/CouchbaseLite/QUERY: {Query#203} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE ((fl_value(_doc.body, 'type') = 'price' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND fl_value(_doc.body, 'item.id') = 'f1ed22fa28ce') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.195 I/QUERY: {Query#203} Compiled as SELECT fl_result(fl_root(_doc.body)), fl_result(_doc.key) FROM kv_default AS _doc WHERE ((fl_value(_doc.body, 'type') = 'price' AND fl_value(_doc.body, 'channels') = '7JFlD2OEV7U2ZBYiBXCC20aEaIL2::khj8xbs2yw3n') AND fl_value(_doc.body, 'item.id') = 'f1ed22fa28ce') AND (_doc.flags & 1 = 0)
2019-11-08 11:10:47.195 I/CouchbaseLite/QUERY: {QueryEnum#204}==> N8litecore21SQLiteQueryEnumeratorE 0x7813d605e8 @0x7813d605e8
2019-11-08 11:10:47.195 I/QUERY: {QueryEnum#204}==> N8litecore21SQLiteQueryEnumeratorE 0x7813d605e8 @0x7813d605e8
2019-11-08 11:10:47.195 I/CouchbaseLite/QUERY: {QueryEnum#204} Created on {Query#203} with 0 rows (2 bytes) in 0.115ms
2019-11-08 11:10:47.195 I/QUERY: {QueryEnum#204} Created on {Query#203} with 0 rows (2 bytes) in 0.115ms
2019-11-08 11:10:47.195 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.195 I/QUERY: End of query enumeration
2019-11-08 11:10:47.209 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} Read 2 local changes up to #1456: sending 'proposeChanges' with sequences #1455 - #1456
2019-11-08 11:10:47.209 I/REPLICATOR: {N8litecore4repl6PusherE#189} Read 2 local changes up to #1456: sending 'proposeChanges' with sequences #1455 - #1456
2019-11-08 11:10:47.209 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=1, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.209 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=1, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.210 I/CouchbaseLite/REPLICATOR: {Repl#184} pushStatus=busy, pullStatus=idle, progress=0/482
2019-11-08 11:10:47.210 I/REPLICATOR: {Repl#184} pushStatus=busy, pullStatus=idle, progress=0/482
2019-11-08 11:10:47.210 I/CouchbaseLite/REPLICATOR: {Repl#184} activityLevel=busy: connectionState=2
2019-11-08 11:10:47.211 I/REPLICATOR: {Repl#184} activityLevel=busy: connectionState=2
2019-11-08 11:10:47.211 I/CouchbaseLite/REPLICATOR: {Repl#184} now busy
2019-11-08 11:10:47.211 I/REPLICATOR: {Repl#184} now busy
2019-11-08 11:10:47.211 D/REPLICATOR: statusChangedCallback() handle: 515869828864, status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=482, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.211 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=1, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.211 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=1, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.211 I/CouchbaseLite/REPLICATOR: C4ReplicatorListener.statusChanged, context: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}], status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=482, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.211 I/REPLICATOR: C4ReplicatorListener.statusChanged, context: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}], status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=482, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.212 I/CouchbaseLite/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}]: status changed: (0, 0) @C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=482, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.212 I/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}]: status changed: (0, 0) @C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=482, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.212 D/NETWORK: C4Socket.write @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.212 I/CouchbaseLite/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}] is busy, progress 0/482, error: null
2019-11-08 11:10:47.212 I/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}] is busy, progress 0/482, error: null
2019-11-08 11:10:47.212 D/NETWORK: C4Socket.completedWrite @515875623232: 264
2019-11-08 11:10:47.221 D/mylog: 318406499855853 replication status = Status{activityLevel=BUSY, progress=Progress{completed=0, total=482}, error=null}
2019-11-08 11:10:47.270 D/NETWORK: C4Socket.received @515875623232: 11
2019-11-08 11:10:47.274 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} Got response for 2 local changes (sequences from 1455)
2019-11-08 11:10:47.274 I/REPLICATOR: {N8litecore4repl6PusherE#189} Got response for 2 local changes (sequences from 1455)
2019-11-08 11:10:47.274 D/NETWORK: C4Socket.completedReceive @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.277 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=2, caughtUp=1, changeLists=0, revsInFlight=2, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.277 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=2, caughtUp=1, changeLists=0, revsInFlight=2, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.277 D/NETWORK: C4Socket.write @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.277 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=2, caughtUp=1, changeLists=0, revsInFlight=1, blobsInFlight=0, awaitingReply=611, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.277 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=2, caughtUp=1, changeLists=0, revsInFlight=1, blobsInFlight=0, awaitingReply=611, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.277 D/NETWORK: C4Socket.completedWrite @515875623232: 260
2019-11-08 11:10:47.279 D/NETWORK: C4Socket.write @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.279 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=2, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.279 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=2, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=2, pendingSequences=2
2019-11-08 11:10:47.279 D/NETWORK: C4Socket.completedWrite @515875623232: 69
2019-11-08 11:10:47.422 I/CouchbaseLite/QUERY: {QueryEnum#205}==> N8litecore21SQLiteQueryEnumeratorE 0x7817095cc8 @0x7817095cc8
2019-11-08 11:10:47.422 I/QUERY: {QueryEnum#205}==> N8litecore21SQLiteQueryEnumeratorE 0x7817095cc8 @0x7817095cc8
2019-11-08 11:10:47.422 I/CouchbaseLite/QUERY: {QueryEnum#205} Created on {Query#24} with 10 rows (2178 bytes) in 0.252ms
2019-11-08 11:10:47.422 I/QUERY: {QueryEnum#205} Created on {Query#24} with 10 rows (2178 bytes) in 0.252ms
2019-11-08 11:10:47.422 I/CouchbaseLite/QUERY: {QueryEnum#205} Deleted
2019-11-08 11:10:47.422 I/QUERY: {QueryEnum#205} Deleted
2019-11-08 11:10:47.422 I/CouchbaseLite/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@ffe85b8 > null
2019-11-08 11:10:47.422 I/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@ffe85b8 > null
2019-11-08 11:10:47.423 I/CouchbaseLite/QUERY: {QueryEnum#206}==> N8litecore21SQLiteQueryEnumeratorE 0x7817095cc8 @0x7817095cc8
2019-11-08 11:10:47.423 I/QUERY: {QueryEnum#206}==> N8litecore21SQLiteQueryEnumeratorE 0x7817095cc8 @0x7817095cc8
2019-11-08 11:10:47.423 I/CouchbaseLite/QUERY: {QueryEnum#206} Created on {Query#26} with 3 rows (946 bytes) in 0.118ms
2019-11-08 11:10:47.423 I/QUERY: {QueryEnum#206} Created on {Query#26} with 3 rows (946 bytes) in 0.118ms
2019-11-08 11:10:47.423 I/CouchbaseLite/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@d5f5ae0 > com.couchbase.lite.ResultSet@74093c
2019-11-08 11:10:47.423 I/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@d5f5ae0 > com.couchbase.lite.ResultSet@74093c
2019-11-08 11:10:47.424 I/CouchbaseLite/QUERY: End of query enumeration
2019-11-08 11:10:47.424 I/QUERY: End of query enumeration
2019-11-08 11:10:47.443 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} Read 1 local changes up to #1457: sending 'proposeChanges' with sequences #1457 - #1457
2019-11-08 11:10:47.443 I/REPLICATOR: {N8litecore4repl6PusherE#189} Read 1 local changes up to #1457: sending 'proposeChanges' with sequences #1457 - #1457
2019-11-08 11:10:47.444 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.444 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.444 I/CouchbaseLite/REPLICATOR: {Repl#184} pushStatus=busy, pullStatus=idle, progress=0/762
2019-11-08 11:10:47.444 I/REPLICATOR: {Repl#184} pushStatus=busy, pullStatus=idle, progress=0/762
2019-11-08 11:10:47.445 I/CouchbaseLite/REPLICATOR: {Repl#184} activityLevel=busy: connectionState=2
2019-11-08 11:10:47.445 I/REPLICATOR: {Repl#184} activityLevel=busy: connectionState=2
2019-11-08 11:10:47.445 D/REPLICATOR: statusChangedCallback() handle: 515869828864, status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=762, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.446 I/CouchbaseLite/REPLICATOR: C4ReplicatorListener.statusChanged, context: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}], status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=762, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.446 I/REPLICATOR: C4ReplicatorListener.statusChanged, context: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}], status: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=762, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.446 D/NETWORK: C4Socket.write @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.446 I/CouchbaseLite/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}]: status changed: (0, 0) @C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=762, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.446 I/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}]: status changed: (0, 0) @C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=0, progressUnitsTotal=762, progressDocumentCount=0, errorDomain=0, errorCode=0, errorInternalInfo=0}
2019-11-08 11:10:47.446 D/NETWORK: C4Socket.completedWrite @515875623232: 98
2019-11-08 11:10:47.447 I/CouchbaseLite/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}] is busy, progress 0/762, error: null
2019-11-08 11:10:47.447 I/REPLICATOR: Replicator{@793fdf7,<*>,Database{@db993c2, name='couchbase_database'},URLEndpoint{url=wss://my.endpoint.com/my_database}] is busy, progress 0/762, error: null
2019-11-08 11:10:47.447 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.447 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=1, revsInFlight=0, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.490 D/NETWORK: C4Socket.received @515875623232: 11
2019-11-08 11:10:47.492 D/NETWORK: C4Socket.completedReceive @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.492 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} Got response for 1 local changes (sequences from 1457)
2019-11-08 11:10:47.492 I/REPLICATOR: {N8litecore4repl6PusherE#189} Got response for 1 local changes (sequences from 1457)
2019-11-08 11:10:47.494 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=0, revsInFlight=1, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.494 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=0, revsInFlight=1, blobsInFlight=0, awaitingReply=1230, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.495 D/NETWORK: C4Socket.write @515875623232: com.couchbase.lite.internal.replicator.CBLWebSocket@9101f18
2019-11-08 11:10:47.495 I/CouchbaseLite/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=1818, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.495 I/REPLICATOR: {N8litecore4repl6PusherE#189} activityLevel=busy: pendingResponseCount=3, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=1818, revsToSend=0, pushingDocs=3, pendingSequences=3
2019-11-08 11:10:47.495 D/NETWORK: C4Socket.completedWrite @515875623232: 155
2019-11-08 11:10:47.496 D/mylog: 318406774617312 replication status = Status{activityLevel=BUSY, progress=Progress{completed=0, total=762}, error=null}
2019-11-08 11:10:47.704 I/CouchbaseLite/QUERY: {QueryEnum#207}==> N8litecore21SQLiteQueryEnumeratorE 0x781704d928 @0x781704d928
2019-11-08 11:10:47.704 I/QUERY: {QueryEnum#207}==> N8litecore21SQLiteQueryEnumeratorE 0x781704d928 @0x781704d928
2019-11-08 11:10:47.704 I/CouchbaseLite/QUERY: {QueryEnum#207} Created on {Query#24} with 10 rows (2178 bytes) in 0.505ms
2019-11-08 11:10:47.704 I/QUERY: {QueryEnum#207} Created on {Query#24} with 10 rows (2178 bytes) in 0.505ms
2019-11-08 11:10:47.704 I/CouchbaseLite/QUERY: {QueryEnum#207} Deleted
2019-11-08 11:10:47.704 I/QUERY: {QueryEnum#207} Deleted
2019-11-08 11:10:47.705 I/CouchbaseLite/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@ffe85b8 > null
2019-11-08 11:10:47.705 I/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@ffe85b8 > null
2019-11-08 11:10:47.705 I/CouchbaseLite/QUERY: {QueryEnum#208}==> N8litecore21SQLiteQueryEnumeratorE 0x781704d928 @0x781704d928
2019-11-08 11:10:47.705 I/QUERY: {QueryEnum#208}==> N8litecore21SQLiteQueryEnumeratorE 0x781704d928 @0x781704d928
2019-11-08 11:10:47.705 I/CouchbaseLite/QUERY: {QueryEnum#208} Created on {Query#26} with 3 rows (946 bytes) in 0.221ms
2019-11-08 11:10:47.705 I/QUERY: {QueryEnum#208} Created on {Query#26} with 3 rows (946 bytes) in 0.221ms
2019-11-08 11:10:47.705 I/CouchbaseLite/QUERY: {QueryEnum#208} Deleted
2019-11-08 11:10:47.705 I/QUERY: {QueryEnum#208} Deleted
2019-11-08 11:10:47.706 I/CouchbaseLite/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@74093c > null
2019-11-08 11:10:47.706 I/QUERY: LiveQuery refresh: com.couchbase.lite.ResultSet@74093c > null
--- no more logs for several minutes. No sync is happening during this time.

The logs show a few queries at first and then that the document update of the device is not pushed. The CBL status is busy. Continuous pull and push sync starts working again after killing the app and then restarting it. I also observed that the busy state (but no sync) happens frequently when reopening the app after it was in the background. In the app the replication is stopped as soon as the app goes into background and is started again once it goes into foreground.

I checked SG warning and error logs and there were no logs. I also looked into nginx error logs and there also was nothing logged.

Would it help if I provide a minimal Android app which demonstrates this behavior in order to find the root cause?

This is a universal truth! A reliable reproduction is often half or more of the battle.

I’ll try to get it done by Monday!

I also observed another interesting detail. I posted above that the sync stops for the device (A) which has the CBL status BUSY. That is incorrect. The device (A) shows the status when a local document update happened. This update is unable to sync up?! But if another device (B) updates a different document it is received and displayed by device (A). So pull replication keeps working.

I created a demo app but was never able to reproduce the issue.

Here are all my findings so far:

  • unable to reproduce with demo app in dev cluster
  • unable to reproduce with production app in dev cluster
  • no issues with production app in production cluster when in beta test phase. ~100 unique users per day
  • Loadbalancer server, web app server, SG servers, Couchbase Server servers have plenty off compute, network and storage resources left unused
  • easily run into issue with production app in production cluster. But not reproducible. Once the issue appeared on one device it’s easy to see it on a different device, too. As far as I can tell only enough time needs to pass since the last time the SG service was last restarted. Yesterday it took around an hour. Today it ran fine for more than half a day and still does run fine.
  • issue appears when
    • app was in background and came to foreground
    • app was plugged in to wall socket and screen was kept on. After some time without using the app the issue appeared after updating a document on the device
  • Restarting the SG service fixes the issue immediately

Important to note

I have been using SG 2.6 for a while already. The described issue only appeared after most users updated to the production app with CBL 2.6/CBL 2.7 SNAPSHOT

Workaround until the issue will be fixed

I could restart the SG service via cron job every so often. Any other recommendations?

Looping in @humpback_whale and @fatmonkey45

Are you still seeing your described issues? In development only? If so are you able to reproduce it in a minimal app you could share? Or did you find a workaround and would like to share it?
I also tested @humpback_whale’s issue but could not reproduce it in production. I can edit documents on Couchbase Server dashboard. After turning airplane mode off the change is pulled down and replicator status goes back to idle.

@benjamin_glatzeder
We are still experiencing the issue with CBL 2.5.3 changing it to CBL 2.6 or 2.7 did not resolve the problem so we kept it on 2.5.3

On the infrastructure side - everything seems to have plenty of compute and storage resources - just like @benjamin_glatzeder observes

We have around 30 users but mostly up to 8 per day, 2 buckets in Couchbase with around 200k documents in each.

The android app has two replicators (per bucket) connecting to the same SG endpoint.

If we reinstall the app on the device the initial sync takes a while (obviously due to number of documents), but once the replicators go into IDLE and we leave the app running for a few minutes or disconnect / reconnect the network - the issue appears.

This happens in our Development and Production environments.

Is there any chance that this has something to do with a firewall/gateway of some kind? It really does sound like something that could happen when some kind of port/address mapping timed out…

My current fix is:

  • Create a user account with only 1 document
  • in loop:
    • Update document periodically
    • Wait several seconds
    • Check if replicator status is still busy
    • if it is still busy then ssh into server and restart SG service

I tested the setup without automatic service restarts for a day or two and could confirm that the sync status was busy (and stopped syncing) on my other devices which ran the production app. The service is restarted between 1 and 3 times per day. I wasn’t able to find any firewall/port time outs. I think my issue is that the write queue grew too big on the SG server as pointed out by @bbrks in this post.