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

Mobile Couchbase Lite
16

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
17

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
18

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

19

@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?

20

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?

21

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

22

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.

23

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

cbldemo_screenshot
cbldemo_screenshot.png480×960 37.6 KB

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.

1 Like
24

@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.

25

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…

1 Like
26

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.

27

The issues I experienced are gone since upgrading to SG version 2.7. Hopefully this will solve your issues, too, @humpback_whale and @fatmonkey45.

Great work all around!

28

Thanks @benjamin_glatzeder for the update!

I have updated both SG and CBL to 2.7, however out of my two buckets that i am replicating one is still having the same issue:

V:NETWORK: WebSocketListener received data of 127 bytes
V:NETWORK: {N8litecore4blip10ConnectionE#11} Finished receiving 'norev' REQ #114341 N
D:NETWORK: C4Socket.received @2919712968: 127
D:NETWORK: C4Socket.completedReceive @2919712968: com.couchbase.lite.internal.replicator.CBLWebSocket@a8b0850
I:REPLICATOR: {N8litecore4repl6PullerE#18} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=193, _activeIncomingRevs=0
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4blip6BLIPIOE#15} Received frame: REQ #114342 --N-, length   123
V:NETWORK: {N8litecore4blip10ConnectionE#11} Receiving 'norev' REQ #114342 N
V:NETWORK: {N8litecore4blip10ConnectionE#11} Finished receiving 'norev' REQ #114342 N
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
D:NETWORK: C4Socket.completedReceive @2919712968: com.couchbase.lite.internal.replicator.CBLWebSocket@a8b0850
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4blip6BLIPIOE#15} Received frame: REQ #114343 --N-, length   123
V:NETWORK: {N8litecore4blip10ConnectionE#11} Receiving 'norev' REQ #114343 N
V:NETWORK: {N8litecore4blip10ConnectionE#11} Finished receiving 'norev' REQ #114343 N
D:NETWORK: C4Socket.completedReceive @2919712968: com.couchbase.lite.internal.replicator.CBLWebSocket@a8b0850
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4blip6BLIPIOE#15} Received frame: REQ #114344 --N-, length   123
V:NETWORK: {N8litecore4blip10ConnectionE#11} Receiving 'norev' REQ #114344 N
V:NETWORK: {N8litecore4blip10ConnectionE#11} Finished receiving 'norev' REQ #114344 N
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
I:REPLICATOR: {N8litecore4repl6PullerE#18} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=192, _activeIncomingRevs=0
I:REPLICATOR: {N8litecore4repl6PullerE#18} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=191, _activeIncomingRevs=0
I:REPLICATOR: {N8litecore4repl6PullerE#18} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=190, _activeIncomingRevs=0
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
V:NETWORK: WebSocketListener received data of 127 bytes
D:NETWORK: C4Socket.received @2919712968: 127
V:NETWORK: {N8litecore4repl12C4SocketImplE#14} Received 127-byte message
29

@fatmonkey45 : That log seems to show a replicator successfully pulling 127-byte messages. We’ll need something that actually shows the replicator state and the number of bytes that are still outstanding, to analyze your issue…

30

I have a similar issue with SG 2.6 and CB 6.0.3 Enterprise edition, my clients use latest Android and iOS CBL. We use one PushAndPull Replicator in our clients. We have only few hundred clients, SG and CB have more than enough resource.
Everyday we have clients complaining about the following scenario:

  1. Two or more devices at one client location push and pull data with the SG, customer is satisfied, replication between the devices is fast.
  2. Everyday some customers complain that part of their devices don’t get replicated while the other devices are replicating. Restarting the app doesn’t help.
  3. Only workaround so far is the restart of the sync gateway, after that all devices get replicated.
31

Running into this stuck BUSY state myself. I’m testing replication recovery after network outage and it doesn’t get unstuck, even after network is restored.
CBL 2.8.1 on Android 10
I’m updating a local document every 30 seconds and logging this every 30 seconds…
Status{activityLevel=BUSY, progress=Progress{completed=12897, total=13083}, error=null}

Thinking about if( completed < total) and completed hasn’t changed in a few minutes, restart the replicator.

-Tim

32

Did you ever find a solution to this, I am stuck on a similar problem ?

33

Not really, but things are more stable than in the past. I am not sure if it was network related.

1 Like
34

Hi, there is more information about this issue over here: Replicator pull continous stop after network error in couchbase lite 2.8.x android - #2 by Giallon

1 Like
35

Upgrading to the latest CBL might help resolving the issue as we have fixed the issues related to the replicator hanging in the past few releases. If that still doesn’t solve, please attach the full verbose logging here. It will be very useful to get full-thread dump when the replicator is hanging.