Never-ending Busy state

Mobile
1

Overview:
Occasionally, I am seeing a sync endpoint go into a never ending busy state. By that I mean - the final SyncCallback with status Idle never happens. When an endpoint gets into this state, it never seems to get out of it. Restarting doesn’t help, only deleting the local DB and recreating it.

Details:
Platform: client = mac + xamarin/c# +Xamarin.Mac Full (== .Net Framework 4.8)
server = ubuntu.

I create a continuous replicator:

        var auth = new BasicAuthenticator(id, GetServerPassword());
        var sync_config = new ReplicatorConfiguration(database, new URLEndpoint(url))
        {
            ReplicatorType = ReplicatorType.PushAndPull,
            Continuous = true,
            Authenticator = auth,
            ConflictResolver = new SyncConflictResolver()
        };
        replicator = new Replicator(sync_config);
        listenerToken = replicator.AddChangeListener(SyncStatusUpdate);
        replicator.Start();

In the function SyncStatusUpdate, I update various UI elements to reflect the current status - Idle, Busy, Error, Not Started…

Normally everything is fine. I make a change to the DB, I see the SyncStatusUpdate called with:

event.Status.Activity == ReplicatorActivityLevel.Busy

and the two values event.Status.Progress.Total and e.Status.Progress.Completed have some values which indicate something is going on (I don’t know exactly what the values mean).

After a few seconds, I see a final call to SyncStatusUpdate with:

event.Status.Activity == ReplicatorActivityLevel.Idle

At this point I change the UI to reflect that the sync being idle.

However sometimes I stop receiving the idle callback. I dont know what causes the app to enter this state.

When happens then is:

  • I make a change to the DB
  • SyncStatusUpdate called with ReplicatorActivityLevel.Busy (one or more times depending on how large the sync data is)
  • SyncStatusUpdate called with ReplicatorActivityLevel.Busy and the total and completed have the same value

but SyncStatusUpdate is never called with Idle. The data actually does sync during this time and I can see this reflected at other endpoints.

This state never changes, meaning that I never see an Idle message, only Busy with total == completed. The fix is to delete the local DB and download all data from scratch.

My questions:

  • Does a Sync Callback with status Busy and total == completed mean the same as status Idle? I seem to remember somewhere that the total/completed values are not to be used literally as a percent done indicator.
  • Why does Idle go away and never come back, at least until I delete the database.

All software is up to date.
Client is a mac, server is ubuntu.

Thanks for any advice you can provide… I’m puzzled.
Cheers.
Paul

p.s. I have attached 4 images - the event.status and event.progress values for the start of a sync event and the end of a sync event (i.e. there is no “Idle” to follow).

Starting:

Bad sync starting status
Bad sync starting status846×208 25.4 KB

Bad sync just starting
Bad sync just starting856×166 24.7 KB

Finishing:

Bad sync finished status
Bad sync finished status848×206 25.3 KB

Bad sync finished
Bad sync finished846×166 23.7 KB

2

Please be sure to include the platform in your posts. The screenshots and code samples are familiar to me as C#, but other people might not realize. This is an area that we’ve had a lot of struggle with, though I can’t remember a case in which things are stuck at busy but also the total and completed are equal. There is no substitute for the idle state, though this might be a close second. The answer as to why is unfortunately not an easy one to answer at all. It’s only ever been recreated as the result of a series of dozens of complex steps. If you can reproduce this reliably then a bug report would be very much appreciated.

3

I’ve added platform details at the top. Apologies for the lack of clarity.

I don’t know how I get in this state so I don’t know how to reproduce. I only know I’m in that state when I see the idle state not being entered, which I suspect may have happened a run or two beforehand (checking logs doesn’t show anything unusual). I do know that once I’m there, its permanent (until the DB is deleted and rebuilt). I figured it was some weird corruption of the local DB.

I am on a dev machine, so the app and db take more abuse (e.g. unnatural shutdowns) than usual. That could be a factor.

I have switched to detecting idle state via both the idle flag and “total == completed”. A positive side effect I’ve noticed is that syncing appears to the user to be much faster, as if the “total==completed” happens well before before the idle state comes through.

If I ever do figure out the steps to make this happen, I’ll let you know.

[One thought… if this is some corrupted state inside the DB file itself, then the next time this happens, I’m going to run a PerformMaintenance(MaintenanceType.IntegrityCheck), and perhaps MaintenanceType.Optimise to see if that makes it go away.]

Thanks for your help.

4

I can report that PerformMaintenance on the local DB does not resolve the issue - I tried IntegrityCheck, FullOptimise and (for grins) Compact. If it is an issue with the local DB - then its not something PerformMaintenance can fix.

I don’t know why it started, but after many application restarts, it has not gone away.

5

It’s unlikely to be an actual issue with the local DB. If the replicator is reporting busy then it is (or thinks it is) waiting for an asynchronous operation to finish. There are many different kinds as the entire pipeline is actor based asynchronous calls so if any of them falsely report that they are still in operation, then that will keep a replicator in the busy state. You should see lines in the log that log replicator status every once in a while along with a bunch of numbers. Those numbers give a clue as to which area the replicator is waiting for (_revisionsInFlight or something like that, a bunch of underscore variables and values).

6

Hi @borrrden

I have some more detail now, and I am sure you are right that its not a local db problem.

I have two instances of my app (one on mac, one on iPad).
Here’s the process once the failure has started to happen. Note that prior to this the app had been perfectly well behaved for a day or so.

  • I make changes on the iPad. I see them syncing to the central DB. The new records appear in couchbase.
  • I start the mac app. It does not see the changes. It seems that the puller is staying in a busy state, and not finding the changes that were made.
  • I can restart the mac app. There is no change - it does not see the changes, and puller is in a permanent busy state.
  • I can make changes in the mac app and they sync to the central DB and down to the iPad.

I have created a log below using:

            Database.Log.Console.Domains = LogDomain.Replicator;
            Database.Log.Console.Level = LogLevel.Verbose;

This log runs from app startup until things stabilise - i.e. there are no more messages in the log.
My apologies for it being so long.

Please note that, for some reason, the log has duplicated messages, including a large section from 04:22:36.506 till 04:22:36.756. This happens every time I run the log. I have checked - I’m not opening the database twice or starting the replication twice - it seems that once I enable logging, messages are coming out twice.

I hope this is of use to you.
All the best.
Paul.

2022-9-15 04:22:36.506+12:00 [1]| VERBOSE)  [Replicator] (Database) [1] There is no saved HTTP cookies.
2022-9-15 04:22:36.509+12:00 [1]| INFO)  [Replicator] (Replicator) [1] Replicator[<*> wss://192.168.1.5:29756/testproject/]: Starting
2022-9-15 04:22:36.510+12:00 [1]| INFO)  [Replicator] {Repl#75}==> litecore::repl::Replicator /Users/Paul/.local/share/testproject.cblite2/ ->wss://192.168.1.5:29756/testproject/_blipsync @0x7fc6b0ee6c10
2022-9-15 04:22:36.511+12:00 [1]| INFO)  [Replicator] {Repl#75} Push=continuous, Pull=continuous, Options={{auth:{password:"********", type:"Basic", username:"testuser"}, autoPurge:true, headers:{User-Agent:"CouchbaseLite/3.0.2 (.NET; Unix 21.6.0.0) Build/3 LiteCore/6fb3bfc417b100fbc65b6c762f4c2d78b9b6ed6c (19) Commit/4e9c4205"}}}
2022-9-15 04:22:36.511+12:00 [1]| INFO)  [Replicator] {C4Replicator#76}==> litecore::C4RemoteReplicator 0x7fc6c13c3ce8 @0x7fc6c13c3ce8
2022-9-15 04:22:36.512+12:00 [1]| VERBOSE)  [Replicator] {C4Replicator#76} C4RemoteRepl 0x7fc6c13c3ce8 created Repl 0x7fc6b0ee6c10
2022-9-15 04:22:36.512+12:00 [1]| INFO)  [Replicator] {C4Replicator#76} Starting Replicator {Repl#75}
2022-9-15 04:22:36.515+12:00 [23]| INFO)  [Replicator] {Repl#75} Scanning for pre-existing conflicts...
2022-9-15 04:22:36.515+12:00 [23]| INFO)  [Replicator] {Repl#75} Found 0 conflicted docs in 0.003 sec
2022-9-15 04:22:36.516+12:00 [1]| INFO)  [Replicator] (Replicator) [1] Replicator[<*> wss://192.168.1.5:29756/testproject/] is Connecting, progress 0/0
2022-9-15 04:22:36.516+12:00 [23]| VERBOSE)  [Replicator] {Repl#75} Remote-DB ID 1 found for target <wss://192.168.1.5:29756/testproject/_blipsync>
2022-9-15 04:22:36.517+12:00 [1]| INFO)  [Replicator] (Replicator) [1] Replicator[<*> wss://192.168.1.5:29756/testproject/] is Connecting, progress 0/0
2022-9-15 04:22:36.517+12:00 [23]| INFO)  [Replicator] {Repl#75} Read local checkpoint 'cp-3+4rftbIf4haKsvo1vjKGOmlf6U=': {"time":1663215246,"local":576}
2022-9-15 04:22:36.517+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=connecting: connectionState=1, savingChkpt=0
2022-9-15 04:22:36.529+12:00 [24]| VERBOSE)  [Replicator] (SerialQueue) [24] DispatchAsync Void <Start>b__31_0()
2022-9-15 04:22:36.530+12:00 [27]| INFO)  [Replicator] (WebSocketWrapper) [27] c4Socket is retained, and reachability status monitor is starting.
2022-9-15 04:22:36.535+12:00 [27]| INFO)  [Replicator] (Reachability) [27] Network change detected, analyzing connection status...
2022-9-15 04:22:36.536+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing lo0 (lo0)...
2022-9-15 04:22:36.536+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     NIC invalid (not outward facing)
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing gif0 (gif0)...
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     NIC invalid (not up)
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing stf0 (stf0)...
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     NIC invalid (not up)
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing en5 (en5)...
2022-9-15 04:22:36.538+12:00 [27]| INFO)  [Replicator] (Reachability) [27] Found Acceptable NIC en5 (en5)
2022-9-15 04:22:36.542+12:00 [27]| INFO)  [Replicator] (Reachability) [27] At least one acceptable IP address found (fe80::aede:48ff:fe00:1122%4), signaling network reachable
2022-9-15 04:22:36.754+12:00 [Thread Pool Worker]| VERBOSE)  [Replicator] (SerialQueue) [Thread Pool Worker (12)] DispatchAsync Void StartInternal()
2022-9-15 04:22:36.756+12:00 [28]| INFO)  [Replicator] (WebSocketWrapper) [28] WebSocket connecting to 192.168.1.5:29756
2022-9-15 04:22:36.506+12:00 [1]| VERBOSE)  [Replicator] (Database) [1] There is no saved HTTP cookies.
2022-9-15 04:22:36.509+12:00 [1]| INFO)  [Replicator] (Replicator) [1] Replicator[<*> wss://192.168.1.5:29756/testproject/]: Starting
2022-9-15 04:22:36.510+12:00 [1]| INFO)  [Replicator] {Repl#75}==> litecore::repl::Replicator /Users/Paul/.local/share/testproject.cblite2/ ->wss://192.168.1.5:29756/testproject/_blipsync @0x7fc6b0ee6c10
2022-9-15 04:22:36.511+12:00 [1]| INFO)  [Replicator] {Repl#75} Push=continuous, Pull=continuous, Options={{auth:{password:"********", type:"Basic", username:"testuser"}, autoPurge:true, headers:{User-Agent:"CouchbaseLite/3.0.2 (.NET; Unix 21.6.0.0) Build/3 LiteCore/6fb3bfc417b100fbc65b6c762f4c2d78b9b6ed6c (19) Commit/4e9c4205"}}}
2022-9-15 04:22:36.511+12:00 [1]| INFO)  [Replicator] {C4Replicator#76}==> litecore::C4RemoteReplicator 0x7fc6c13c3ce8 @0x7fc6c13c3ce8
2022-9-15 04:22:36.512+12:00 [1]| VERBOSE)  [Replicator] {C4Replicator#76} C4RemoteRepl 0x7fc6c13c3ce8 created Repl 0x7fc6b0ee6c10
2022-9-15 04:22:36.512+12:00 [1]| INFO)  [Replicator] {C4Replicator#76} Starting Replicator {Repl#75}
2022-9-15 04:22:36.515+12:00 [23]| INFO)  [Replicator] {Repl#75} Scanning for pre-existing conflicts...
2022-9-15 04:22:36.515+12:00 [23]| INFO)  [Replicator] {Repl#75} Found 0 conflicted docs in 0.003 sec
2022-9-15 04:22:36.516+12:00 [1]| INFO)  [Replicator] (Replicator) [1] Replicator[<*> wss://192.168.1.5:29756/testproject/] is Connecting, progress 0/0
2022-9-15 04:22:36.516+12:00 [23]| VERBOSE)  [Replicator] {Repl#75} Remote-DB ID 1 found for target <wss://192.168.1.5:29756/testproject/_blipsync>
2022-9-15 04:22:36.517+12:00 [1]| INFO)  [Replicator] (Replicator) [1] Replicator[<*> wss://192.168.1.5:29756/testproject/] is Connecting, progress 0/0
2022-9-15 04:22:36.517+12:00 [23]| INFO)  [Replicator] {Repl#75} Read local checkpoint 'cp-3+4rftbIf4haKsvo1vjKGOmlf6U=': {"time":1663215246,"local":576}
2022-9-15 04:22:36.517+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=connecting: connectionState=1, savingChkpt=0
2022-9-15 04:22:36.529+12:00 [24]| VERBOSE)  [Replicator] (SerialQueue) [24] DispatchAsync Void <Start>b__31_0()
2022-9-15 04:22:36.530+12:00 [27]| INFO)  [Replicator] (WebSocketWrapper) [27] c4Socket is retained, and reachability status monitor is starting.
2022-9-15 04:22:36.535+12:00 [27]| INFO)  [Replicator] (Reachability) [27] Network change detected, analyzing connection status...
2022-9-15 04:22:36.536+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing lo0 (lo0)...
2022-9-15 04:22:36.536+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     NIC invalid (not outward facing)
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing gif0 (gif0)...
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     NIC invalid (not up)
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing stf0 (stf0)...
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     NIC invalid (not up)
2022-9-15 04:22:36.537+12:00 [27]| VERBOSE)  [Replicator] (Reachability) [27]     Testing en5 (en5)...
2022-9-15 04:22:36.538+12:00 [27]| INFO)  [Replicator] (Reachability) [27] Found Acceptable NIC en5 (en5)
2022-9-15 04:22:36.542+12:00 [27]| INFO)  [Replicator] (Reachability) [27] At least one acceptable IP address found (fe80::aede:48ff:fe00:1122%4), signaling network reachable
2022-9-15 04:22:36.754+12:00 [Thread Pool Worker]| VERBOSE)  [Replicator] (SerialQueue) [Thread Pool Worker (12)] DispatchAsync Void StartInternal()
2022-9-15 04:22:36.756+12:00 [28]| INFO)  [Replicator] (WebSocketWrapper) [28] WebSocket connecting to 192.168.1.5:29756
2022-9-15 04:22:37.204+12:00 [Thread Pool Worker]| VERBOSE)  [Replicator] (SerialQueue) [Thread Pool Worker (12)] DispatchAsync Void OnSocketReady()
2022-9-15 04:22:37.208+12:00 [Thread Pool Worker]| VERBOSE)  [Replicator] (SerialQueue) [Thread Pool Worker (18)] DispatchAsync Void HandleHTTPResponse()
2022-9-15 04:22:37.211+12:00 [30]| VERBOSE)  [Replicator] (WebSocketWrapper) [30] WebSocket sent HTTP request...
2022-9-15 04:22:37.204+12:00 [Thread Pool Worker]| VERBOSE)  [Replicator] (SerialQueue) [Thread Pool Worker (12)] DispatchAsync Void OnSocketReady()
2022-9-15 04:22:37.208+12:00 [Thread Pool Worker]| VERBOSE)  [Replicator] (SerialQueue) [Thread Pool Worker (18)] DispatchAsync Void HandleHTTPResponse()
2022-9-15 04:22:37.211+12:00 [30]| VERBOSE)  [Replicator] (WebSocketWrapper) [30] WebSocket sent HTTP request...
2022-9-15 04:22:37.426+12:00 [Thread Pool Worker]| INFO)  [Replicator] (WebSocketWrapper) [Thread Pool Worker (9)] WebSocket CONNECTED!
2022-9-15 04:22:37.427+12:00 [31]| VERBOSE)  [Replicator] (WebSocketWrapper) [31] c4Socket got http response.
2022-9-15 04:22:37.428+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=connecting: connectionState=1, savingChkpt=0
2022-9-15 04:22:37.428+12:00 [23]| INFO)  [Replicator] {Repl#75} Connected!
2022-9-15 04:22:37.428+12:00 [31]| INFO)  [Replicator] (WebSocketWrapper) [31] c4Socket is open.
2022-9-15 04:22:37.429+12:00 [23]| VERBOSE)  [Replicator] {Repl#75} Requesting remote checkpoint 'cp-3+4rftbIf4haKsvo1vjKGOmlf6U='
2022-9-15 04:22:37.430+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.431+12:00 [23]| INFO)  [Replicator] {Repl#75} now busy
2022-9-15 04:22:37.431+12:00 [23]| INFO)  [Replicator] {C4Replicator#76} State: busy, progress=0.00%
2022-9-15 04:22:37.433+12:00 [23]| INFO)  [Replicator] (Replicator) [23] Replicator[<*> wss://192.168.1.5:29756/testproject/] is Busy, progress 0/0
2022-9-15 04:22:37.435+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.437+12:00 [33]| VERBOSE)  [Replicator] (WebSocketWrapper) [33] c4Socket completed Write.
2022-9-15 04:22:37.643+12:00 [34]| VERBOSE)  [Replicator] (WebSocketWrapper) [34] <<< received 82 bytes [now 82 pending]
2022-9-15 04:22:37.646+12:00 [23]| INFO)  [Replicator] {Repl#75} Received remote checkpoint (rev='0-397'): {"local":576,"time":1663215246}
2022-9-15 04:22:37.647+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.648+12:00 [35]| VERBOSE)  [Replicator] (WebSocketWrapper) [35] c4Socket received.
2022-9-15 04:22:37.649+12:00 [24]| INFO)  [Replicator] {Pusher#81}==> litecore::repl::Pusher {Repl#75} @0x7fc6c13c9490
2022-9-15 04:22:37.650+12:00 [24]| INFO)  [Replicator] {Pusher#81} Starting continuous push from local seq #577
2022-9-15 04:22:37.651+12:00 [37]| INFO)  [Replicator] {Puller#82}==> litecore::repl::Puller {Repl#75} @0x7fc6c13c9720
2022-9-15 04:22:37.651+12:00 [37]| INFO)  [Replicator] {Puller#82} Starting pull from remote seq ''
2022-9-15 04:22:37.652+12:00 [24]| INFO)  [Replicator] {ReplicatorChangesFeed#83}==> litecore::repl::ReplicatorChangesFeed 0x7fc6c13c95b8 @0x7fc6c13c95b8
2022-9-15 04:22:37.652+12:00 [37]| INFO)  [Replicator] {Puller#82} msg["revocations"]="true" due to enableAutoPurge()=1 or progressNotificationLevel()=0 > 0
2022-9-15 04:22:37.653+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Starting DB observer
2022-9-15 04:22:37.653+12:00 [37]| INFO)  [Replicator] {Puller#82} activityLevel=busy: pendingResponseCount=1, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
2022-9-15 04:22:37.654+12:00 [37]| VERBOSE)  [Replicator] {Puller#82} now busy
2022-9-15 04:22:37.654+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Reading up to 200 local changes since #576
2022-9-15 04:22:37.655+12:00 [38]| INFO)  [Replicator] {Repl#75} pushStatus=busy, pullStatus=busy, progress=0/0
2022-9-15 04:22:37.656+12:00 [38]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.656+12:00 [37]| INFO)  [Replicator] {Puller#82} activityLevel=busy: pendingResponseCount=1, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
2022-9-15 04:22:37.657+12:00 [24]| INFO)  [Replicator] {Pusher#81} Found 0 changes up to #576
2022-9-15 04:22:37.657+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=busy: pendingResponseCount=0, caughtUp=0, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.658+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} now busy
2022-9-15 04:22:37.658+12:00 [37]| INFO)  [Replicator] {Repl#75} pushStatus=busy, pullStatus=busy, progress=0/0
2022-9-15 04:22:37.659+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Asking DB observer for 200 new changes since sequence #576 ...
2022-9-15 04:22:37.659+12:00 [24]| INFO)  [Replicator] {ReplicatorChangesFeed#83} No new observed changes...
2022-9-15 04:22:37.660+12:00 [39]| VERBOSE)  [Replicator] (WebSocketWrapper) [39] c4Socket completed Write.
2022-9-15 04:22:37.660+12:00 [24]| INFO)  [Replicator] {Pusher#81} Found 0 changes up to #576
2022-9-15 04:22:37.661+12:00 [37]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.662+12:00 [24]| INFO)  [Replicator] {Pusher#81} Caught up, at lastSequence #576
2022-9-15 04:22:37.662+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=busy: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.663+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Asking DB observer for 200 new changes since sequence #576 ...
2022-9-15 04:22:37.663+12:00 [24]| INFO)  [Replicator] {ReplicatorChangesFeed#83} No new observed changes...
2022-9-15 04:22:37.663+12:00 [24]| INFO)  [Replicator] {Pusher#81} Found 0 changes up to #576
2022-9-15 04:22:37.664+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=busy: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.664+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=idle: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.665+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} now idle
2022-9-15 04:22:37.666+12:00 [40]| VERBOSE)  [Replicator] (WebSocketWrapper) [40] c4Socket completed Write.
2022-9-15 04:22:37.666+12:00 [37]| INFO)  [Replicator] {Repl#75} pushStatus=idle, pullStatus=busy, progress=0/0
2022-9-15 04:22:37.667+12:00 [37]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.668+12:00 [41]| VERBOSE)  [Replicator] (WebSocketWrapper) [41] c4Socket completed Write.
2022-9-15 04:22:37.669+12:00 [42]| VERBOSE)  [Replicator] (WebSocketWrapper) [42] c4Socket completed Write.
2022-9-15 04:22:37.426+12:00 [Thread Pool Worker]| INFO)  [Replicator] (WebSocketWrapper) [Thread Pool Worker (9)] WebSocket CONNECTED!
2022-9-15 04:22:37.427+12:00 [31]| VERBOSE)  [Replicator] (WebSocketWrapper) [31] c4Socket got http response.
2022-9-15 04:22:37.428+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=connecting: connectionState=1, savingChkpt=0
2022-9-15 04:22:37.428+12:00 [23]| INFO)  [Replicator] {Repl#75} Connected!
2022-9-15 04:22:37.428+12:00 [31]| INFO)  [Replicator] (WebSocketWrapper) [31] c4Socket is open.
2022-9-15 04:22:37.429+12:00 [23]| VERBOSE)  [Replicator] {Repl#75} Requesting remote checkpoint 'cp-3+4rftbIf4haKsvo1vjKGOmlf6U='
2022-9-15 04:22:37.430+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.431+12:00 [23]| INFO)  [Replicator] {Repl#75} now busy
2022-9-15 04:22:37.431+12:00 [23]| INFO)  [Replicator] {C4Replicator#76} State: busy, progress=0.00%
2022-9-15 04:22:37.433+12:00 [23]| INFO)  [Replicator] (Replicator) [23] Replicator[<*> wss://192.168.1.5:29756/testproject/] is Busy, progress 0/0
2022-9-15 04:22:37.435+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.437+12:00 [33]| VERBOSE)  [Replicator] (WebSocketWrapper) [33] c4Socket completed Write.
2022-9-15 04:22:37.643+12:00 [34]| VERBOSE)  [Replicator] (WebSocketWrapper) [34] <<< received 82 bytes [now 82 pending]
2022-9-15 04:22:37.646+12:00 [23]| INFO)  [Replicator] {Repl#75} Received remote checkpoint (rev='0-397'): {"local":576,"time":1663215246}
2022-9-15 04:22:37.647+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.648+12:00 [35]| VERBOSE)  [Replicator] (WebSocketWrapper) [35] c4Socket received.
2022-9-15 04:22:37.649+12:00 [24]| INFO)  [Replicator] {Pusher#81}==> litecore::repl::Pusher {Repl#75} @0x7fc6c13c9490
2022-9-15 04:22:37.650+12:00 [24]| INFO)  [Replicator] {Pusher#81} Starting continuous push from local seq #577
2022-9-15 04:22:37.651+12:00 [37]| INFO)  [Replicator] {Puller#82}==> litecore::repl::Puller {Repl#75} @0x7fc6c13c9720
2022-9-15 04:22:37.651+12:00 [37]| INFO)  [Replicator] {Puller#82} Starting pull from remote seq ''
2022-9-15 04:22:37.652+12:00 [24]| INFO)  [Replicator] {ReplicatorChangesFeed#83}==> litecore::repl::ReplicatorChangesFeed 0x7fc6c13c95b8 @0x7fc6c13c95b8
2022-9-15 04:22:37.652+12:00 [37]| INFO)  [Replicator] {Puller#82} msg["revocations"]="true" due to enableAutoPurge()=1 or progressNotificationLevel()=0 > 0
2022-9-15 04:22:37.653+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Starting DB observer
2022-9-15 04:22:37.653+12:00 [37]| INFO)  [Replicator] {Puller#82} activityLevel=busy: pendingResponseCount=1, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
2022-9-15 04:22:37.654+12:00 [37]| VERBOSE)  [Replicator] {Puller#82} now busy
2022-9-15 04:22:37.654+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Reading up to 200 local changes since #576
2022-9-15 04:22:37.655+12:00 [38]| INFO)  [Replicator] {Repl#75} pushStatus=busy, pullStatus=busy, progress=0/0
2022-9-15 04:22:37.656+12:00 [38]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.656+12:00 [37]| INFO)  [Replicator] {Puller#82} activityLevel=busy: pendingResponseCount=1, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
2022-9-15 04:22:37.657+12:00 [24]| INFO)  [Replicator] {Pusher#81} Found 0 changes up to #576
2022-9-15 04:22:37.657+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=busy: pendingResponseCount=0, caughtUp=0, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.658+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} now busy
2022-9-15 04:22:37.658+12:00 [37]| INFO)  [Replicator] {Repl#75} pushStatus=busy, pullStatus=busy, progress=0/0
2022-9-15 04:22:37.659+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Asking DB observer for 200 new changes since sequence #576 ...
2022-9-15 04:22:37.659+12:00 [24]| INFO)  [Replicator] {ReplicatorChangesFeed#83} No new observed changes...
2022-9-15 04:22:37.660+12:00 [39]| VERBOSE)  [Replicator] (WebSocketWrapper) [39] c4Socket completed Write.
2022-9-15 04:22:37.660+12:00 [24]| INFO)  [Replicator] {Pusher#81} Found 0 changes up to #576
2022-9-15 04:22:37.661+12:00 [37]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.662+12:00 [24]| INFO)  [Replicator] {Pusher#81} Caught up, at lastSequence #576
2022-9-15 04:22:37.662+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=busy: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.663+12:00 [24]| VERBOSE)  [Replicator] {ReplicatorChangesFeed#83} Asking DB observer for 200 new changes since sequence #576 ...
2022-9-15 04:22:37.663+12:00 [24]| INFO)  [Replicator] {ReplicatorChangesFeed#83} No new observed changes...
2022-9-15 04:22:37.663+12:00 [24]| INFO)  [Replicator] {Pusher#81} Found 0 changes up to #576
2022-9-15 04:22:37.664+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=busy: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.664+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=idle: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
2022-9-15 04:22:37.665+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} now idle
2022-9-15 04:22:37.666+12:00 [40]| VERBOSE)  [Replicator] (WebSocketWrapper) [40] c4Socket completed Write.
2022-9-15 04:22:37.666+12:00 [37]| INFO)  [Replicator] {Repl#75} pushStatus=idle, pullStatus=busy, progress=0/0
2022-9-15 04:22:37.667+12:00 [37]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 04:22:37.668+12:00 [41]| VERBOSE)  [Replicator] (WebSocketWrapper) [41] c4Socket completed Write.
2022-9-15 04:22:37.669+12:00 [42]| VERBOSE)  [Replicator] (WebSocketWrapper) [42] c4Socket completed Write.
2022-9-15 04:22:37.863+12:00 [43]| VERBOSE)  [Replicator] (WebSocketWrapper) [43] <<< received 9 bytes [now 9 pending]
2022-9-15 04:22:37.867+12:00 [44]| VERBOSE)  [Replicator] (WebSocketWrapper) [44] c4Socket received.
2022-9-15 04:22:37.865+12:00 [37]| INFO)  [Replicator] {Puller#82} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
2022-9-15 04:22:37.863+12:00 [43]| VERBOSE)  [Replicator] (WebSocketWrapper) [43] <<< received 9 bytes [now 9 pending]
2022-9-15 04:22:37.867+12:00 [44]| VERBOSE)  [Replicator] (WebSocketWrapper) [44] c4Socket received.
2022-9-15 04:22:37.865+12:00 [37]| INFO)  [Replicator] {Puller#82} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
7

The duplicated log messages are interesting and not something I’ve seen anyone point out before. As for the replication itself, it appears that the puller is waiting for a signal that there are no more changes from the other side (as evidenced by _caughtUp = 0). I see a non standard port being used in your remote address. Does this, by any chance, mean that you are running a proxy on your server? The logs for the Puller show almost no activity, which suggests that it is not correctly receiving messages from the network.

8

Thanks for the quick response.
The non-std port is just habit really. I always move ports when possible - ssh, wireguard etc.
Its just to make all services less of an easy target when I eventually make it public.

There is a proxy involved. Let me test restarting it and the server to see if that changes things.
I’ll also try without the proxy.

Cheers.
Paul.

9

I think the dup messages are something to do with VS… one set appear blue, another set appear black. Its not a concern.

Screen Shot 2022-09-15 at 7.09.26 PM
Screen Shot 2022-09-15 at 7.09.26 PM1566×530 175 KB

10

Proxies are a big source of problems when it comes to replication unless they are configured correctly for web socket traffic. That’s not my area of expertise but you can analyze the traffic going back and forth using Wireshark, which ships with a BLIP decoder (the network protocol we use). As for the blue and black messages, I think to be clever we write to both the console and the .NET Debug trace, which might be why they show up twice.

11

Bypassed the proxy… so I am going directly to the sync server on port 4984 with TLS disabled. Restart the app.
I see the same problem:

2022-9-15 07:15:33.908+12:00 [31]| INFO)  [Replicator] (Replicator) [31] Replicator[<*> ws://sync1:4984/testproject/] is Busy, progress 793840/794188
2022-9-15 07:15:33.909+12:00 [31]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=1
2022-9-15 07:15:34.091+12:00 [56]| VERBOSE)  [Replicator] (WebSocketWrapper) [56] <<< received 9 bytes [now 9 pending]
2022-9-15 07:15:34.093+12:00 [57]| VERBOSE)  [Replicator] (WebSocketWrapper) [57] c4Socket received.
2022-9-15 07:15:34.094+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} Completed rev yCk16psaBGnsKexe0rDLlg #1-7266abf5e01ab9c30b7eb398239a77b6924517b9 (seq #550)
2022-9-15 07:15:34.096+12:00 [24]| INFO)  [Replicator] {Pusher#81} Checkpoint now [0-574, 576]
2022-9-15 07:15:34.096+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} progress +348/+0, 1 docs -- now 794188 / 794188, 1 docs
2022-9-15 07:15:34.096+12:00 [24]| INFO)  [Replicator] {Pusher#81} activityLevel=idle: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=1
2022-9-15 07:15:34.097+12:00 [24]| VERBOSE)  [Replicator] {Pusher#81} now idle
2022-9-15 07:15:34.097+12:00 [31]| INFO)  [Replicator] {Repl#75} pushStatus=idle, pullStatus=busy, progress=794188/794188
2022-9-15 07:15:34.098+12:00 [31]| VERBOSE)  [Replicator] {Repl#75} progress +348/+0, 1 docs -- now 794188 / 794188, 1 docs
2022-9-15 07:15:34.098+12:00 [31]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=1
2022-9-15 07:15:34.098+12:00 [31]| VERBOSE)  [Replicator] {Repl#75} Saving remote checkpoint 'cp-4nJY6LCYfGaR0Buo3Ib6K8wfXvc=' over rev='': {"time":1663226134,"local":574,"localCompleted":[0,575,576,1]} ...
2022-9-15 07:15:34.098+12:00 [31]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=1
2022-9-15 07:15:34.099+12:00 [31]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=1
2022-9-15 07:15:34.100+12:00 [59]| VERBOSE)  [Replicator] (WebSocketWrapper) [59] c4Socket completed Write.
2022-9-15 07:15:34.107+12:00 [24]| INFO)  [Replicator] {C4Replicator#76} State: busy, progress=100.00%
2022-9-15 07:15:34.108+12:00 [24]| INFO)  [Replicator] (Replicator) [24] Replicator[<*> ws://sync1:4984/testproject/] is Busy, progress 794188/794188
2022-9-15 07:15:34.109+12:00 [24]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=1
2022-9-15 07:15:34.120+12:00 [48]| VERBOSE)  [Replicator] {DBAccess#86} Marked 1 revs as synced-to-server in 0.23ms (4371/sec)
2022-9-15 07:15:34.520+12:00 [61]| VERBOSE)  [Replicator] (WebSocketWrapper) [61] <<< received 17 bytes [now 17 pending]
2022-9-15 07:15:34.523+12:00 [62]| VERBOSE)  [Replicator] (WebSocketWrapper) [62] c4Socket received.
2022-9-15 07:15:34.524+12:00 [31]| INFO)  [Replicator] {Repl#75} Saved remote checkpoint 'cp-4nJY6LCYfGaR0Buo3Ib6K8wfXvc=' as rev='0-1'
2022-9-15 07:15:34.525+12:00 [31]| INFO)  [Replicator] {Repl#75} Saved local checkpoint 'cp-4nJY6LCYfGaR0Buo3Ib6K8wfXvc=': {"time":1663226134,"local":574,"localCompleted":[0,575,576,1]}
2022-9-15 07:15:34.525+12:00 [31]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
2022-9-15 07:15:34.520+12:00 [61]| VERBOSE)  [Replicator] (WebSocketWrapper) [61] <<< received 17 bytes [now 17 pending]
2022-9-15 07:15:34.523+12:00 [62]| VERBOSE)  [Replicator] (WebSocketWrapper) [62] c4Socket received.
2022-9-15 07:15:34.524+12:00 [31]| INFO)  [Replicator] {Repl#75} Saved remote checkpoint 'cp-4nJY6LCYfGaR0Buo3Ib6K8wfXvc=' as rev='0-1'
2022-9-15 07:15:34.525+12:00 [31]| INFO)  [Replicator] {Repl#75} Saved local checkpoint 'cp-4nJY6LCYfGaR0Buo3Ib6K8wfXvc=': {"time":1663226134,"local":574,"localCompleted":[0,575,576,1]}
2022-9-15 07:15:34.525+12:00 [31]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0
12

These logs don’t have any Puller information in them at all so the only thing I can do with it is wildly guess. Do the Sync Gateway logs show anything unusual? They should show changes and such being computed. I have yet to see any changes come through for your app, and also have yet to see a message about the puller getting caught up. The lack of caught up is what is causing the problem, but that is something that gets sent from Sync Gateway. It seems like you are reliably able to reproduce the issue on your end, but is the setup something you can share? If so then if you send it over in a bug report it will probably not be a very long task to figure out what is going on. Otherwise, the complete start to finish logs from both lite and sync gateway are the next step (and a wireshark trace if possible).

13

Darn! Sorry… so many lines in the logs. I missed the most important. Doh!


2022-9-15 07:42:53.342+12:00 [24]| INFO)  [Replicator] {Puller#83} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0
2022-9-15 07:42:53.348+12:00 [23]| INFO)  [Replicator] {Repl#75} activityLevel=busy: connectionState=2, savingChkpt=0

I appreciate your help. Per your suggestion I’m going to dig in to the server side. I’ll let you know if anything leaps out.

14

Yeah… it looks like plenty of errors on the server side. Here is the message set that appears straight after the application connects:

2022-09-15T07:50:43.409Z [INF] HTTP+: #187:     --> 101 [632d8a88] Upgraded to WebSocket protocol BLIP_3+CBMobile_3 (as <ud>b6J9tuWwTVVp</ud>)  (0.0 ms)
2022-09-15T07:50:43.409Z [INF] WS: c:#187 Start BLIP/Websocket handler
2022-09-15T07:50:43.614Z [INF] SyncMsg: c:[632d8a88] #1: Type:getCheckpoint Client:cp-4nJY6LCYfGaR0Buo3Ib6K8wfXvc=
2022-09-15T07:50:43.821Z [INF] SyncMsg: c:[632d8a88] #2: Type:subChanges Since:0 Continuous:true 
2022-09-15T07:50:43.821Z [INF] Sync: c:[632d8a88] Sending changes since 0
2022-09-15T07:50:43.821Z [INF] Changes: c:[632d8a88] MultiChangesFeed(channels: <ud>{*}</ud>, options: {Since: 0, Limit: 0, Conflicts: false, IncludeDocs: false, Wait: true, Continuous: true, HeartbeatMs: 0, TimeoutMs: 0, ActiveOnly: false}) ... <ud>  (to b6J9tuWwTVVp)</ud>
2022-09-15T07:50:43.822Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>dzbTMVAXVkEBSEdk3LeSUm</ud>", 81742:0) --> 16 changes valid from #1
2022-09-15T07:50:43.822Z [INF] Cache:   Querying 'channels' for "<ud>nfmtqaXFe4HnfYEG7bvVsv</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.822Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>yb0qpC1sERIk1khH7zRP43</ud>", 81769:0) --> 50 changes valid from #88138
2022-09-15T07:50:43.822Z [INF] Cache:   Querying 'channels' for "<ud>yb0qpC1sERIk1khH7zRP43</ud>" (start=#1, end=#88138, limit=5000)
2022-09-15T07:50:43.822Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>b6J9tuWwTVVp</ud>", 81549:0) --> 40 changes valid from #1
2022-09-15T07:50:43.822Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>ymYXS1VjwNsgZEh4tm42xZ</ud>", 88247:0) --> 17 changes valid from #1
2022-09-15T07:50:43.822Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>LeiZ0bI5TlIlZdZz5vNgYP</ud>", 81581:0) --> 50 changes valid from #101277
2022-09-15T07:50:43.822Z [INF] Cache:   Querying 'channels' for "<ud>LeiZ0bI5TlIlZdZz5vNgYP</ud>" (start=#1, end=#101277, limit=5000)
2022-09-15T07:50:43.822Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>kK6sBtlouSziT9Ju44WzUf</ud>", 81567:0) --> 6 changes valid from #1
2022-09-15T07:50:43.822Z [INF] Cache:   Querying 'channels' for "<ud>oAXyRKJoZ04lWw0rbXv15G</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.822Z [INF] Cache:   Querying 'channels' for "<ud>C54UWmchuGME244aGHULHn</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>brkGfERfTDwwqiih8rFo37</ud>", 81786:0) --> 4 changes valid from #1
2022-09-15T07:50:43.823Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>2rMrgkmLD7KIue8kNmbfbP</ud>", 81558:0) --> 6 changes valid from #1
2022-09-15T07:50:43.823Z [INF] Cache: c:[632d8a88] GetCachedChanges("<ud>8LVWb57yiffRM5ijLUV53x</ud>", 81717:0) --> 50 changes valid from #88199
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>8LVWb57yiffRM5ijLUV53x</ud>" (start=#1, end=#88199, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>a5bl16ZxNttYURgNFwcoSV</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>9cP6jeGdljIalen3tpZ4Qv</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>RXLTHZu1x4u6KQ5Qn9gYbu</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>dav2Z1BBFQmDLfcquBuUja</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>eKH7B2RxVVg4yTNLUrB9FJ</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>f1Udx91SF5bEAJPChKvk2t</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.823Z [INF] Cache:   Querying 'channels' for "<ud>nBax2x4uo7EqcjHMTprPau</ud>" (start=#1, end=#18446744073709551615, limit=5000)
2022-09-15T07:50:43.859Z [INF] Cache:     Got 4 rows from query for "<ud>f1Udx91SF5bEAJPChKvk2t</ud>": #88495 ... #88499
2022-09-15T07:50:43.860Z [INF] Cache:     Got 4 rows from query for "<ud>nBax2x4uo7EqcjHMTprPau</ud>": #88278 ... #88281
2022-09-15T07:50:43.860Z [INF] Cache:     Got 2 rows from query for "<ud>oAXyRKJoZ04lWw0rbXv15G</ud>": #81711 ... #81712
2022-09-15T07:50:43.860Z [INF] Cache:     Got 7 rows from query for "<ud>nfmtqaXFe4HnfYEG7bvVsv</ud>": #81815 ... #81825
2022-09-15T07:50:43.861Z [INF] Cache:     Got 2 rows from query for "<ud>C54UWmchuGME244aGHULHn</ud>": #81708 ... #81709
2022-09-15T07:50:43.861Z [INF] Cache:     Got 38 rows from query for "<ud>yb0qpC1sERIk1khH7zRP43</ud>": #81771 ... #88138
2022-09-15T07:50:43.861Z [INF] Cache:   Added 37 entries from query (#81771--#88137) to cache of "<ud>yb0qpC1sERIk1khH7zRP43</ud>"
2022-09-15T07:50:43.861Z [INF] Cache: c:[632d8a88] GetChangesInChannel("<ud>yb0qpC1sERIk1khH7zRP43</ud>") --> 87 rows
2022-09-15T07:50:43.861Z [INF] Cache:     Got 48 rows from query for "<ud>a5bl16ZxNttYURgNFwcoSV</ud>": #97716 ... #100338
2022-09-15T07:50:43.862Z [INF] Cache:     Got 8 rows from query for "<ud>9cP6jeGdljIalen3tpZ4Qv</ud>": #89769 ... #100710
2022-09-15T07:50:43.862Z [INF] Cache:     Got 22 rows from query for "<ud>8LVWb57yiffRM5ijLUV53x</ud>": #81718 ... #88199
2022-09-15T07:50:43.862Z [INF] Cache:   Added 21 entries from query (#81718--#88198) to cache of "<ud>8LVWb57yiffRM5ijLUV53x</ud>"
2022-09-15T07:50:43.862Z [INF] Cache: c:[632d8a88] GetChangesInChannel("<ud>8LVWb57yiffRM5ijLUV53x</ud>") --> 71 rows
2022-09-15T07:50:43.862Z [WRN] c:[632d8a88] Error checking document history during revocation, seq: 81710:81708 in channel <ud>C54UWmchuGME244aGHULHn</ud>, ending revocation feed. Error: SubdocGetBodyAndXattr <ud>C54UWmchuGME244aGHULHn</ud>: Not Found -- db.(*Database).buildRevokedFeed.func1() at changes.go:250
2022-09-15T07:50:43.862Z [WRN] c:[632d8a88] Error checking document history during revocation, seq: 81713:81711 in channel <ud>oAXyRKJoZ04lWw0rbXv15G</ud>, ending revocation feed. Error: SubdocGetBodyAndXattr <ud>oAXyRKJoZ04lWw0rbXv15G</ud>: Not Found -- db.(*Database).buildRevokedFeed.func1() at changes.go:250
2022-09-15T07:50:43.863Z [INF] Cache:     Got 9 rows from query for "<ud>dav2Z1BBFQmDLfcquBuUja</ud>": #88558 ... #88566
2022-09-15T07:50:43.863Z [WRN] c:[632d8a88] Error checking document history during revocation, seq: 81826:81817 in channel <ud>nfmtqaXFe4HnfYEG7bvVsv</ud>, ending revocation feed. Error: SubdocGetBodyAndXattr <ud>Bg1GgrIoBRDDr5U3wBvM31</ud>: Not Found -- db.(*Database).buildRevokedFeed.func1() at changes.go:250
2022-09-15T07:50:43.863Z [WRN] c:[632d8a88] Error checking document history during revocation, seq: 100711:89769 in channel <ud>9cP6jeGdljIalen3tpZ4Qv</ud>, ending revocation feed. Error: SubdocGetBodyAndXattr <ud>jSi0ABl1E8ipxW6GJVB7cb</ud>: Not Found -- db.(*Database).buildRevokedFeed.func1() at changes.go:250
2022-09-15T07:50:43.864Z [INF] Cache:     Got 15 rows from query for "<ud>eKH7B2RxVVg4yTNLUrB9FJ</ud>": #81853 ... #81908
2022-09-15T07:50:43.867Z [INF] Cache:     Got 85 rows from query for "<ud>RXLTHZu1x4u6KQ5Qn9gYbu</ud>": #88393 ... #88477
2022-09-15T07:50:43.881Z [INF] Cache:     Got 725 rows from query for "<ud>LeiZ0bI5TlIlZdZz5vNgYP</ud>": #81582 ... #101277
2022-09-15T07:50:43.881Z [INF] Cache:   Added 450 entries from query (#82637--#101276) to cache of "<ud>LeiZ0bI5TlIlZdZz5vNgYP</ud>"
2022-09-15T07:50:43.881Z [INF] Cache: c:[632d8a88] GetChangesInChannel("<ud>LeiZ0bI5TlIlZdZz5vNgYP</ud>") --> 774 rows
2022-09-15T07:50:43.881Z [WRN] c:[632d8a88] MultiChangesFeed got error reading changes feed: Error while building channel feed -- db.(*Database).SimpleMultiChangesFeed.func1() at changes.go:847
2022-09-15T07:50:43.881Z [INF] Changes: c:[632d8a88] MultiChangesFeed done <ud>  (to b6J9tuWwTVVp)</ud>
2022-09-15T07:50:43.881Z [WRN] c:[632d8a88] Error checking document history during revocation, seq: 81910:81856 in channel <ud>eKH7B2RxVVg4yTNLUrB9FJ</ud>, ending revocation feed. Error: SubdocGetBodyAndXattr <ud>IIy8f2EF69H35KpDt7Rubc</ud>: Not Found -- db.(*Database).buildRevokedFeed.func1() at changes.go:250
2022-09-15T07:50:44.015Z [INF] SyncMsg: c:[632d8a88] #3: Type:proposeChanges #Changes: 0
2022-09-15T07:50:44.015Z [INF] SyncMsg: c:[632d8a88] #4: Type:proposeChanges #Changes: 0
2022-09-15T07:50:44.015Z [INF] SyncMsg: c:[632d8a88] #5: Type:proposeChanges #Changes: 0
2022-09-15T07:50:49.042Z [INF] HTTP:  #188: GET /
2022-09-15T07:50:49.042Z [INF] HTTP+: #188:     --> 200   (0.1 ms)

None of the IDs mentioned in the error statements refer to documents that are currently not syncing, but I guess that the errors are causing the client to be unable to pull changes.

15

Sorry for the delay! Our notification system is sometimes weird and I get no ping about replies to topics. I’d have to ask the opinion of someone else like @bbrks with regards to the server logs to see if there is anything misbehaving there that could cause this.