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

humpback_whale · October 15, 2019, 1:47am

Hello all,
As the title descript, I disconnect my device from the internet and update a value in the couchbase server dashboard. After internet reconnection, I saw the following log :
W/CouchbaseLite/NETWORK: C4Socket.completedReceive() handle -> 4089772456
W/CouchbaseLite/NETWORK: C4Socket.write() handle -> 4089772456
W/CouchbaseLite/NETWORK: completedWrite(long) handle -> 4089772456, byteCount -> 268
V/CouchbaseManager$Abstra: Replicator busy
V/CouchbaseManager$Abstra: Replicator busy
Replicator not turing back to idle. And the updated value not push to my CBL.

I am developing this on Android Studio. I tried this on both CBL 2.5.3 and 2.6.0. They all behave the same.
The replicator is set to push and pull mode, I also set it to continuous mode.

Thank you

jens · October 15, 2019, 4:32pm

It looks like you have network logging enabled but not sync logging. Please enable sync logging.

humpback_whale · October 15, 2019, 6:45pm

@jens thank you for your suggestion. I set the logging domain to all and level to debug. Here is the log when it stuck in busy. I read through them, only found that the replicator seems stuck on the last document(3352). But I can’t understand why it is stuck on the last document.

V/CouchbaseLite/NETWORK: WebSocketListener.onMessage() bytes -> 030822dd7e0b42f69bea1a5b189a195a26a519a7245b985aa426a6241999985926251a27999a5b1a589a2bc5c60200695004c8
V/CouchbaseLite/NETWORK: {N8litecore4blip6BLIPIOE#7} Received frame: REQ #3 ---C, length    49
V/CouchbaseLite/NETWORK: {N8litecore4blip10ConnectionE#3} Receiving 'changes' REQ #3 Z
V/CouchbaseLite/NETWORK: {N8litecore4blip10ConnectionE#3} Finished receiving 'changes' REQ #3 Z
V/CouchbaseLite/REPLICATOR: {Pull#9} Received 'changes' REQ#3 (0 queued; 0 revs pending, 0 active)
V/CouchbaseLite/REPLICATOR: {Pull#9} Handling 'changes' REQ#3
I/CouchbaseLite/REPLICATOR: {Pull#9} activityLevel=busy: pendingResponseCount=0, _caughtUp=1, _waitingForChangesCallback=1, _pendingRevMessages=0, _activeIncomingRevs=0
V/CouchbaseLite/REPLICATOR: {Pull#9} now busy
I/CouchbaseLite/REPLICATOR: {Repl#4} pushStatus=idle, pullStatus=busy, dbStatus=idle, progress=3351/3351
I/CouchbaseLite/REPLICATOR: {Repl#4} activityLevel=busy: connectionState=2
I/CouchbaseLite/REPLICATOR: {DBWorker#6} Received 1 changes (seq '78'..'78')
I/CouchbaseLite/REPLICATOR: {DBWorker#6} Responded to 'changes' REQ#3 w/request for 1 revs
V/CouchbaseLite/REPLICATOR: {Pull#9} Now waiting for 1 'rev' messages; 1 known sequences pending
V/CouchbaseLite/REPLICATOR: {Pull#9} progress +0/+1, 0 docs -- now 0 / 1, 0 docs
I/CouchbaseLite/REPLICATOR: {Pull#9} activityLevel=busy: pendingResponseCount=0, _caughtUp=1, _waitingForChangesCallback=0, _pendingRevMessages=1, _activeIncomingRevs=0
I/CouchbaseLite/REPLICATOR: {DBWorker#6} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
I/CouchbaseLite/REPLICATOR: {Repl#4} now busy
V/CouchbaseLite/NETWORK: {N8litecore4blip6BLIPIOE#7} Sending RES #3 Z
V/CouchbaseLite/NETWORK: {N8litecore4blip6BLIPIOE#7}     Sending frame: RES #3 ---C, bytes 0--260
I/CouchbaseLite/REPLICATOR: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=3351, progressUnitsTotal=3351, progressDocumentCount=1, errorDomain=0, errorCode=0, errorInternalInfo=0}
W/C4Socket: completedWrite(long) handle -> 4089772456, byteCount -> 263
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@127cc839{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}]: status changed: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=3351, progressUnitsTotal=3351, progressDocumentCount=1, errorDomain=0, errorCode=0, errorInternalInfo=0}
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@127cc839{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}] is busy, progress 3351/3351, error: null
V/CouchbaseManager$Abstra: Replicator busy
I/CouchbaseLite/REPLICATOR: {Repl#4} pushStatus=idle, pullStatus=busy, dbStatus=idle, progress=3351/3352
V/CouchbaseLite/NETWORK: {N8litecore4blip6BLIPIOE#7} Finished sending RES #3 Z
V/CouchbaseLite/NETWORK: {N8litecore4blip6BLIPIOE#7} ...Wrote 263 bytes to WebSocket (writeable=1)
V/CouchbaseLite/REPLICATOR: {Repl#4} progress +0/+1, 0 docs -- now 3351 / 3352, 1 docs
I/CouchbaseLite/REPLICATOR: {Repl#4} activityLevel=busy: connectionState=2
I/CouchbaseLite/REPLICATOR: {Repl#4} activityLevel=busy: connectionState=2
I/CouchbaseLite/REPLICATOR: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=3351, progressUnitsTotal=3352, progressDocumentCount=1, errorDomain=0, errorCode=0, errorInternalInfo=0}
I/CouchbaseLite/REPLICATOR: {Repl#4} activityLevel=busy: connectionState=2
I/CouchbaseLite/REPLICATOR: {Repl#4} activityLevel=busy: connectionState=2
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@127cc839{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}]: status changed: C4ReplicatorStatus{activityLevel=4, progressUnitsCompleted=3351, progressUnitsTotal=3352, progressDocumentCount=1, errorDomain=0, errorCode=0, errorInternalInfo=0}
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@127cc839{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}] is busy, progress 3351/3352, error: null
V/CouchbaseManager$Abstra: Replicator busy

After about 6 minutes, the websocket disconnected, and connection with sync gateway reestablished.

W/CouchbaseLite/NETWORK: WebSocketListener.onFailure() response -> null: java.io.EOFException
I/CouchbaseLite/NETWORK: {N8litecore4repl12C4SocketImplE#10}==> N8litecore4repl12C4SocketImplE wss://config.test.com/channel/demo/_blipsync @0xf3c4f218
I/CouchbaseLite/NETWORK: {N8litecore4repl12C4SocketImplE#10} Socket disconnected! (reason=1, code=104)
I/CouchbaseLite/NETWORK: {N8litecore4repl12C4SocketImplE#10} sent 1373 bytes, rcvd 303, in 405.932 sec (3/sec, 1/sec)
I/CouchbaseLite/NETWORK: {N8litecore4blip10ConnectionE#3} Closed with errno 104: Connection reset by peer
I/CouchbaseLite/REPLICATOR: {Repl#4} Connection closed with errno 104: "Connection reset by peer" (state=2)
I/CouchbaseLite/REPLICATOR: {DBWorker#6} activityLevel=idle: pendingResponseCount=0, eventCount=1, activeDocs=0
E/CouchbaseLite/REPLICATOR: {Repl#4} Got LiteCore error: POSIX error 104 "Connection reset by peer"
V/CouchbaseLite/REPLICATOR: {Repl#4} progress +0/+0, 0 docs -- now 3547 / 3548, 1 docs
I/CouchbaseLite/REPLICATOR: {Repl#4} activityLevel=stopped: connectionState=-1
I/CouchbaseLite/REPLICATOR: {Repl#4} now stopped
I/CouchbaseLite/REPLICATOR: {Push#8} activityLevel=stopped: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pendingSequences=0
V/CouchbaseLite/REPLICATOR: {Push#8} now stopped
I/CouchbaseLite/REPLICATOR: BLIP sent 8 msgs (1373 bytes), rcvd 3 msgs (303 bytes) in 405.960 sec. Max outbox depth was 1, avg 1.00
I/CouchbaseLite/REPLICATOR: {Pull#9} activityLevel=stopped: pendingResponseCount=0, _caughtUp=1, _waitingForChangesCallback=0, _pendingRevMessages=1, _activeIncomingRevs=0
V/CouchbaseLite/REPLICATOR: {Pull#9} now stopped
I/CouchbaseLite/REPLICATOR: C4ReplicatorListener.statusChanged() status -> C4ReplicatorStatus{activityLevel=0, progressUnitsCompleted=3547, progressUnitsTotal=3548, progressDocumentCount=1, errorDomain=2, errorCode=104, errorInternalInfo=1000}
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@1873d32e{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}]: status changed: C4ReplicatorStatus{activityLevel=0, progressUnitsCompleted=3547, progressUnitsTotal=3548, progressDocumentCount=1, errorDomain=2, errorCode=104, errorInternalInfo=1000}
V/CouchbaseLite/DATABASE: {DB#2} Pre-close housekeeping: 2 of 14 pages free (0%)
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@1873d32e{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}]: Transient error (C4Error{domain=2, code=104, internalInfo=1000}); will retry in 2 sec...
V/CouchbaseLite/REPLICATOR: com.couchbase.lite.AndroidNetworkReachabilityManager@6a68e18: startListening() registering com.couchbase.lite.AndroidNetworkReachabilityManager$NetworkReceiver@12c60071 with context 
V/CouchbaseLite/DATABASE: {DB#2} Closed SQLite database
I/CouchbaseLite/DATABASE: {DB#2} Closing database
I/CouchbaseLite/REPLICATOR: Replicator[<*> Database@1873d32e{name='demo'} URLEndpoint{url=wss://config.test.com/channel/demo}] is offline, progress 3547/3548, error: CouchbaseLiteException{domain='POSIXErrorDomain', code=104, msg=Connection reset by peer}
I/CouchbaseManager$Abstra: Replicator offline
E/CouchbaseManager$Abstra: CouchbaseLiteException{domain='POSIXErrorDomain', code=104, msg=Connection reset by peer}

jens · October 15, 2019, 11:57pm

In the first log, the replicator is waiting to receive one revision from the server (Now waiting for 1 'rev' messages; 1 known sequences pending), but it never arrives, at least in the part of the log you’ve shown.

I’m suspicious of the line

W/C4Socket: completedWrite(long) handle -> 4089772456, byteCount -> 263

It’s a warning, so it may indicate a network error, but LiteCore doesn’t get notified of the error. This warning message seems to be in JNI or Java code since I can’t find it in LiteCore itself. @blake.meike, do you know what that warning means?

humpback_whale · October 16, 2019, 12:59am

Does this have anything to do with Sync Gateway? Does any Sync gateway setting have anything to do with reconnection after losing the previous connection?

humpback_whale · October 17, 2019, 10:00pm

@jens For couchbase-lite-android, is there any way that I could change the default heartbeat interval for the WebSocket connection? I think this might be the parameter but there is no documentation on how to config it. Please clarify me if I am wrong. Thank you!

jens · October 22, 2019, 11:55pm

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

humpback_whale · October 23, 2019, 8:17pm

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.

jens · October 24, 2019, 8:03pm

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.

blake.meike · October 24, 2019, 8:45pm

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…

jens · October 24, 2019, 9:21pm

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.

fatmonkey45 · October 24, 2019, 10:24pm

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

jens · October 26, 2019, 12:37am

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

fatmonkey45 · October 29, 2019, 1:47am

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

borrrden · October 29, 2019, 3:01am

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.

fatmonkey45 · October 29, 2019, 3:10am

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

humpback_whale · October 30, 2019, 10:01pm

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

jens · November 1, 2019, 6:19pm

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

fatmonkey45 · November 8, 2019, 3:02am

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

benjamin_glatzeder · November 8, 2019, 10:35am

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?

Topic		Replies	Views
Force sync when Replicator is offline Couchbase Lite	3	994	July 15, 2019
Q: Continuous replicator halt, the sync stop Mobile	5	914	May 29, 2019
C# Xamarin Replicator Never Leaves Buy State Mobile	4	696	November 28, 2018
Couchbase Lite - Replicator - handling Offline state Couchbase Lite	1	679	April 8, 2020
App Crash during the pull replication with CB Lite v2.6 Couchbase Lite	6	1510	November 12, 2021

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

Setup:

CBL logs

Related topics