Sync gateway not syncing documents with cb lite, replicator stuck on busy

Mobile Sync Gateway
1

Hi all,

we’re experiencing the issue that documents are not synced to couchbase lite (using the Flutter cbl package Version 3.1.1 and tested with 3.1.0, cbl | Dart Package)

Sync on cb lite is stuck on “busy state”, but sync gateway throws no errors.
All data is accessible using sync gateway RETS API or changes feed.

We have found that restarting sync gateway while cb lite doesn’t have all documents will sync all documents. If cb lite replicator is then restarted, it once again gets stuck on 0%.

Here are the sync gateway and cb lite debug logs:
logs.zip (31.8 KB)

File sgw_logs_working_after_restart.log shows the sync gateway logs.
At 2023-08-07T16:06:39.616+02:00 we have restarted the sync gateway and afterwards the documents were correctly synced (once, after restarting cb lite it was back to being stuck on busy).
sg_err.log and sg_warn.log are both empty during that time.

Timestamps in mobile log are timezone -02:00.

We have upgraded sync gateway 3.1.1, config is the same as described here Http: panic serving <IP>: runtime error: invalid memory address or nil pointer dereference after sync gateway upgrade to 3.1 - #5 by fifteen_renditions

{
    "ADMIN": true,
    "couchdb": "Welcome",
    "vendor": {
        "name": "Couchbase Sync Gateway",
        "version": "3.1"
    },
    "version": "Couchbase Sync Gateway/3.1.1(20;d26ad31) EE",
    "persistent_config": true
}

I can’t reproduce the bug better right now and can’t find any information about what could be wrong.
Any help here is greatly appreciated!

2

I know very little about either DART or Flutter but let me see if I can see what’s up, here.

First suspicious thing: there is a pretty big hole in the logs between 12:06:39 and 12:07:15.

12:06:39.908333| [Changes]: {N8litecore15SequenceTrackerE#36} commit: sequences #29 -- #29
12:07:15.524308| [WS]: {N8litecore9websocket16BuiltInWebSocketE#88} sent 359 bytes, rcvd 58, in 36.504 sec (10/sec, 2/sec)

Is the entire app hung?

3

Hi :slight_smile:,

no, the app was running fine and other CBL requests like queries would still have been possible. Maybe @gabriel can give a little bit of support here?

4

I’ve taken a look at the logs and have a few things to note.

  1. There seems to be a bug in the ID generation of outgoing BLIP messages. It is always 0.
12:06:39.020669| [BLIPMessages]: SENDING: REQ #0  {
	Profile: getCheckpoint
	client: cp-aVJJc8xvVx+dGCJSYFGvRTj+lLM= }
12:06:39.021149| [BLIPMessages]: SENDING: REQ #0 UN {
	Profile: proposeChanges
	conflictIncludesRev: true
	BODY: [] }
12:06:39.021198| [BLIPMessages]: SENDING: REQ #0  {
	Profile: subChanges
	continuous: true
	batch: 200
	versioning: rev-trees
	revocations: true }
  1. Shortly before the hole in the logs mentioned by @blake.meike the replicator seems to receive an empty response from the Sync Gateway, but I don’t know enough about the BLIP protocol to tell if this is expected:
12:06:39.053573| [BLIPMessages]: RECEIVED: RES #3  { }

  1. You are using continuous replication. It could be worth trying one-shot replication to see if the issue is related to continuous replication.

  2. There seem to be change listeners for document/database changes. It would be interesting to see if not listening to changes during continuous replication makes a difference. A while back, there was a bug related to continuous replication and change listeners, which has been fixed meanwhile, but it reminded my that those things could interact.

5

" It is always 0" – this is a log issue. Could you also the BLIP log, turning it to Debug?

LogDomain        BLIPLog("BLIP", LogLevel::Warning);
6

Sorry, I’m not quite sure what you mean. The Dart/Flutter SDK that is being used here is built on top of the C SDK, so only APIs exposed from there can be used.

7

How do you turn on the “BlipMessages” log?

8

I tested points 3 & 4, however, I did not observe any changed behavior. Additionally, I tested if the reset of the local checkpoints has any effect, but unfortunately, it has not. The replicator gets still stuck on busy from the beginning.

9

How do you turn on the “BlipMessages” log?

They are turned on in CBLLog_Init.

10

Could you please send a log here with your annotation as where/when do you think replicator is stuck at busy? In the log in the first message, I saw all 20 docs were pulled down and the replicator went to idle.

11

For CBL, you can go via the timestamp (for some reason it is timezone -02:00). The replicator got stuck at 12:06:39.908333 and the SGW was restarted at 12:07:15.524308. For the experiments, where we waited longer, the logs look similar.

Here an extraction from the CBL info log with one error message.

12:06:39.051181| [Zip]: {N8litecore4blip8InflaterE#107} Copying 7 bytes into 4096-byte buf (no compression)
12:06:39.051193| [BLIPMessages]: RECEIVED: ERR #1  {
	Error-Domain: HTTP
	Error-Code: 404
	BODY: missing }
12:06:39.051202| [Sync]: {Repl#84} {Coll#-1} No remote checkpoint 'cp-aVJJc8xvVx+dGCJSYFGvRTj+lLM=' of the default collection
12:06:39.051210| [Sync]: {Repl#84} {Coll#-1} activityLevel=busy: connectionState=2, savingChkpt=0
12:06:39.053561| [Zip]: {N8litecore4blip8InflaterE#107} Copying 1 bytes into 5-byte buf (no compression)
12:06:39.053573| [BLIPMessages]: RECEIVED: RES #3  { }
12:06:39.053582| [Sync]: {N8litecore4repl6PullerE#101} {Coll#0} activityLevel=busy: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0, _waitingRevMessages=0, _unfinishedIncomingRevs=0
....
12:06:39.829576| [Query]: {QueryEnum#152} Deleted
12:06:39.906552| [Changes]: {N8litecore15SequenceTrackerE#36} begin transaction at #28
12:06:39.907215| [DB]: Need to read rev-tree of doc 'user_settings'
12:06:39.907293| [Changes]: {N8litecore24CollectionChangeNotifierE#3} posting notification
12:06:39.907299| [Changes]: {N8litecore24CollectionChangeNotifierE#3} readChanges(100) -> 1 changes
12:06:39.907309| [Changes]: {N8litecore24CollectionChangeNotifierE#3} readChanges(100) -> 0 changes
12:06:39.908333| [Changes]: {N8litecore15SequenceTrackerE#36} commit: sequences #29 -- #29

Here the SGW was restarted - no other logs inbetween

12:07:15.524308| [WS]: {N8litecore9websocket16BuiltInWebSocketE#88} sent 359 bytes, rcvd 58, in 36.504 sec (10/sec, 2/sec)
12:07:15.528331| [Sync]: {Repl#84} {Coll#-1} Connection closed with errno 104: "Connection reset by peer" (state=2)
12:07:15.528675| [Sync]: {Repl#84} {Coll#-1} activityLevel=busy: connectionState=-1, savingChkpt=0
12:07:15.528828| [Sync]: {N8litecore4repl6PusherE#98} {Coll#0} activityLevel=stopped: pendingResponseCount=0, caughtUp=1, changeLists=0, revsInFlight=0, blobsInFlight=0, awaitingReply=0, revsToSend=0, pushingDocs=0, pendingSequences=0
12:07:15.528906| [Sync]: {N8litecore4repl6PullerE#101} {Coll#0} activityLevel=stopped: pendingResponseCount=0, _caughtUp=0, _pendingRevMessages=0, _activeIncomingRevs=0, _waitingRevMessages=0, _unfinishedIncomingRevs=0
12:07:15.528974| [Sync]: {Repl#84} {Coll#-1} pushStatus=stopped, pullStatus=busy, progress=0/0/0
12:07:15.529043| [Sync]: {Repl#84} {Coll#-1} activityLevel=busy: connectionState=-1, savingChkpt=0
12:07:15.529074| [Sync]: {Repl#84} {Coll#-1} pushStatus=stopped, pullStatus=stopped, progress=0/0/0
12:07:15.529151| [Sync]: {Repl#84} {Coll#-1} activityLevel=stopped: connectionState=-1, savingChkpt=0
12:07:15.529185| [Sync]: {Repl#84} {Coll#-1} now stopped
...
12:07:19.000557| [Sync]: {N8litecore4repl6PullerE#176} {Coll#0} activityLevel=busy: pendingResponseCount=0, _caughtUp=1, _pendingRevMessages=8, _activeIncomingRevs=7, _waitingRevMessages=0, _unfinishedIncomingRevs=3
12:07:19.000587| [Sync]: {Repl#170} {Coll#-1} pushStatus=idle, pullStatus=busy, progress=2/20/0
12:07:19.000610| [Sync]: {Repl#170} {Coll#-1} activityLevel=busy: connectionState=2, savingChkpt=1
12:07:19.000633| [Sync]: {C4Replicator#76} State: busy, progress=10.00%
12:07:19.000642| [Sync]: CBLReplicator status: busy, progress=2/20, flag=2, error=0/0 (effective status=busy, completed=0.10%, docs=0)
12:07:19.000691| [Changes]: {N8litecore15SequenceTrackerE#188} begin transaction at #4
12:07:19.002078| [Changes]: {N8litecore15SequenceTrackerE#188} commit: sequences #5 -- #4
12:07:19.002090| [Sync]: {N8litecore4repl8InserterE#185} {Coll#0} Inserted   2 revs in   1.43ms ( 1398/sec) of which 99.9% was commit

From there everything went until idle
12

Do you have the SGW logs before being stuck?

13

We have this behaviour only with a couple of users.
After deleting the sync gateway user and created it again it works again.

The newly created user already has the direct access channels given, then I’ve assigned him the admin channels/roles again.

Tested it with a user with 4 admin channels, 2 admin roles and 4 direct access channels plus the ‘!’ channel.

14

This is the content of the SGW log file:

2023-08-07T16:06:38.414+02:00 [DBG] Auth+: c:#6435 db:db OIDCUsername: <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>
2023-08-07T16:06:38.415+02:00 [INF] HTTP: c:#6435 db:db POST /db/_session (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)
2023-08-07T16:06:39.575+02:00 [INF] HTTP: c:#6440 db:db GET /db/_blipsync (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)
2023-08-07T16:06:39.575+02:00 [INF] HTTP+: c:[28df1a5c] #6440:     --> 101 [28df1a5c] Upgraded to WebSocket protocol BLIP_3+ (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)  (0.0 ms)
2023-08-07T16:06:39.608+02:00 [INF] Changes: MultiChangesFeed(channels: {<ud>*</ud>}, options: {Since: 0, Limit: 0, Conflicts: false, IncludeDocs: false, Wait: true, Continuous: true, HeartbeatMs: 0, TimeoutMs: 0, ActiveOnly: false, RequestPlusSeq: 0}) ... <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: MultiChangesFeed: channels expand to "<ud>!:1,C_DOCUMENT_461218a9-0ddd-48e1-bb6f-eda2764255c4:14828718,C_DOCUMENT_5dfdf48d-e016-424e-bcf1-f6d98e96bc80:14828705,C_DOCUMENT_af87c828-aa37-46cd-835f-e72ae33aa4e3:14986820,C_DOCUMENT_dd463945-3c8b-4607-953a-b9fba6cb90d5:14854808,ar_inc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b:14986840,ar_out_3a0c5a8a-08ec-4279-ab37-eed0586eb89b:14986840,dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b:14986840,dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c:14986839,si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c:14986839,si_out_35498408-f4f5-41f8-9c28-cda0ee49229c:14986839</ud>" ... <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14828705:14477861 in channel <ud>C_DOCUMENT_5dfdf48d-e016-424e-bcf1-f6d98e96bc80</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14872648 in channel <ud>C_DOCUMENT_dd463945-3c8b-4607-953a-b9fba6cb90d5</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477857 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477858 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986820:14985486 in channel <ud>C_DOCUMENT_af87c828-aa37-46cd-835f-e72ae33aa4e3</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986820:14985488 in channel <ud>C_DOCUMENT_af87c828-aa37-46cd-835f-e72ae33aa4e3</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14828705:14477862 in channel <ud>C_DOCUMENT_5dfdf48d-e016-424e-bcf1-f6d98e96bc80</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14872649 in channel <ud>C_DOCUMENT_dd463945-3c8b-4607-953a-b9fba6cb90d5</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477857 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477858 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477857 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14828718:14477857 in channel <ud>C_DOCUMENT_461218a9-0ddd-48e1-bb6f-eda2764255c4</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14828718:14477858 in channel <ud>C_DOCUMENT_461218a9-0ddd-48e1-bb6f-eda2764255c4</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.609+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477858 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.616+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477861 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.616+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477861 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:06:39.616+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477861 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>

Here the SGW was restarted - no other logs inbetween

2023-08-07T16:07:19.228+02:00 [INF] HTTP: c:#004 db:db GET /db/_blipsync (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)
2023-08-07T16:07:19.229+02:00 [INF] HTTP+: c:[6dcb1ce3] #004:     --> 101 [6dcb1ce3] Upgraded to WebSocket protocol BLIP_3+ (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)  (0.0 ms)
2023-08-07T16:07:19.255+02:00 [INF] Changes: MultiChangesFeed(channels: {<ud>*</ud>}, options: {Since: 0, Limit: 0, Conflicts: false, IncludeDocs: false, Wait: true, Continuous: true, HeartbeatMs: 0, TimeoutMs: 0, ActiveOnly: true, RequestPlusSeq: 0}) ... <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.256+02:00 [DBG] Changes+: MultiChangesFeed: channels expand to "<ud>!:1,C_DOCUMENT_461218a9-0ddd-48e1-bb6f-eda2764255c4:14828718,C_DOCUMENT_5dfdf48d-e016-424e-bcf1-f6d98e96bc80:14828705,C_DOCUMENT_af87c828-aa37-46cd-835f-e72ae33aa4e3:14986820,C_DOCUMENT_dd463945-3c8b-4607-953a-b9fba6cb90d5:14854808,ar_inc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b:14986840,ar_out_3a0c5a8a-08ec-4279-ab37-eed0586eb89b:14986840,dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b:14986840,dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c:14986839,si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c:14986839,si_out_35498408-f4f5-41f8-9c28-cda0ee49229c:14986839</ud>" ... <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.267+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477857 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.267+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477858 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.267+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477861 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986820:14985486 in channel <ud>C_DOCUMENT_af87c828-aa37-46cd-835f-e72ae33aa4e3</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986820:14985488 in channel <ud>C_DOCUMENT_af87c828-aa37-46cd-835f-e72ae33aa4e3</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477857 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477858 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14828718:14477857 in channel <ud>C_DOCUMENT_461218a9-0ddd-48e1-bb6f-eda2764255c4</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14828718:14477858 in channel <ud>C_DOCUMENT_461218a9-0ddd-48e1-bb6f-eda2764255c4</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477857 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477858 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477861 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477861 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14828705:14477861 in channel <ud>C_DOCUMENT_5dfdf48d-e016-424e-bcf1-f6d98e96bc80</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.268+02:00 [DBG] Changes+: Channel feed processing seq:14828705:14477862 in channel <ud>C_DOCUMENT_5dfdf48d-e016-424e-bcf1-f6d98e96bc80</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14872648 in channel <ud>C_DOCUMENT_dd463945-3c8b-4607-953a-b9fba6cb90d5</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14872649 in channel <ud>C_DOCUMENT_dd463945-3c8b-4607-953a-b9fba6cb90d5</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14828705:14477861, ID:5dfdf48d-e016-424e-bcf1-f6d98e96bc80, Changes:[map[rev:3-5af2a4284c0e5798024cf57d2fa7f657]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14828705:14477862, ID:3f400593-1380-470a-aaa9-f9138b30475c, Changes:[map[rev:3-a723e8713df7e059d7a22ae12ff55dee]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14828718:14477857, ID:461218a9-0ddd-48e1-bb6f-eda2764255c4, Changes:[map[rev:3-c3bf1ff58af79160df92d99a6d50bbed]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14828718:14477858, ID:9cdf4918-97b9-4772-84b2-a7a8bd33ee52, Changes:[map[rev:3-060e5e81b2febbb7d177315ebc7ac4b8]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14872648, ID:dd463945-3c8b-4607-953a-b9fba6cb90d5, Changes:[map[rev:3-128b6f2694ecad600f40692fe1e40b37]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14872649, ID:7495929a-851f-4653-85c7-c55fa8f27376, Changes:[map[rev:3-a965f94b6dc591859bec8688b0c0ecd1]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986820:14985486, ID:e0607c91-d762-47c6-87ad-4f4adea909fb, Changes:[map[rev:1-bfd7feabccb1537ed2ec973b9f82dbdc]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986820:14985488, ID:af87c828-aa37-46cd-835f-e72ae33aa4e3, Changes:[map[rev:1-5aabdc64fd8e7daf455549168b2c2d3a]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986839:14477857, ID:461218a9-0ddd-48e1-bb6f-eda2764255c4, Changes:[map[rev:3-c3bf1ff58af79160df92d99a6d50bbed]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986839:14477858, ID:9cdf4918-97b9-4772-84b2-a7a8bd33ee52, Changes:[map[rev:3-060e5e81b2febbb7d177315ebc7ac4b8]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986839:14477861, ID:5dfdf48d-e016-424e-bcf1-f6d98e96bc80, Changes:[map[rev:3-5af2a4284c0e5798024cf57d2fa7f657]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477862 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14477862 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14872648 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14872648 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14872649 in channel <ud>si_inc_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986839:14477862, ID:3f400593-1380-470a-aaa9-f9138b30475c, Changes:[map[rev:3-a723e8713df7e059d7a22ae12ff55dee]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986839:14872648, ID:dd463945-3c8b-4607-953a-b9fba6cb90d5, Changes:[map[rev:3-128b6f2694ecad600f40692fe1e40b37]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986839:14872649 in channel <ud>dn_pr_35498408-f4f5-41f8-9c28-cda0ee49229c</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986839:14872649, ID:7495929a-851f-4653-85c7-c55fa8f27376, Changes:[map[rev:3-a965f94b6dc591859bec8688b0c0ecd1]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840:14477857, ID:461218a9-0ddd-48e1-bb6f-eda2764255c4, Changes:[map[rev:3-c3bf1ff58af79160df92d99a6d50bbed]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840:14477858, ID:9cdf4918-97b9-4772-84b2-a7a8bd33ee52, Changes:[map[rev:3-060e5e81b2febbb7d177315ebc7ac4b8]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840:14477861, ID:5dfdf48d-e016-424e-bcf1-f6d98e96bc80, Changes:[map[rev:3-5af2a4284c0e5798024cf57d2fa7f657]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14477862 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14872648 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: Channel feed processing seq:14986840:14872649 in channel <ud>dn_cc_3a0c5a8a-08ec-4279-ab37-eed0586eb89b</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840:14477862, ID:3f400593-1380-470a-aaa9-f9138b30475c, Changes:[map[rev:3-a723e8713df7e059d7a22ae12ff55dee]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840:14872648, ID:dd463945-3c8b-4607-953a-b9fba6cb90d5, Changes:[map[rev:3-128b6f2694ecad600f40692fe1e40b37]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840:14872649, ID:7495929a-851f-4653-85c7-c55fa8f27376, Changes:[map[rev:3-a965f94b6dc591859bec8688b0c0ecd1]]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed sending <ud>{Seq:14986840, ID:_user/login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479, Changes:[]}</ud> <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: MultiChangesFeed waiting... <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
2023-08-07T16:07:19.269+02:00 [DBG] Changes+: 14986840 MultiChangesFeed initial replication caught up - setting ActiveOnly to false... <ud>  (to login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479)</ud>
15

The logs are from before and after being stuck - but filtered on output including the affected user’s ID.

There are a log of logs from unrelated usage, but I can include them if this is helpful.

16

Does this error affect all the devices ? I see the same kind of behaviour (CBL stops syncing) on iOS for only 2 or 3 people, and it started happening after upgrading CBL to 3.1.

17

If affects only some users, but for affected users it’s broken on all devices. So we tested to login with the same user on a different phone, and still didn’t work.

Also because deleting and re-creating affected users in sync gateway fixes it (temporarily), we believe it’s account specific.

18

Not all relevant SG logging information has the user attached to it. When CBL starts a replication, it’ll log like:

2023-08-07T16:06:39.575+02:00 [INF] HTTP: c:#6440 db:db GET /db/_blipsync (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)
2023-08-07T16:06:39.575+02:00 [INF] HTTP+: c:[28df1a5c] #6440:     --> 101 [28df1a5c] Upgraded to WebSocket protocol BLIP_3+ (as <ud>login.vestigas.com%2Fauth%2Frealms%2Fvestigas_d65bee91-0b36-4aef-bae8-b9d9115bf479</ud>)  (0.0 ms)
2

then it will log information on that connection with c:[28df1a5c] or 6440 so searching for 28df1a5c and 6440 is necessary to understand what’s going on.

19

Thanks for the info, now I know how to better follow it!
Here are the complete logs, first being stuck, then sgw restart and then documents were synced (once). After mobile app restart, sync is stuck again.

Restart is at 2023-08-08T23:12:29.299+02:00

Used a different user with more documents this time, with id 24b52290-7d9f-46f0-9d10-8be8d0973fab

debug_hung_working_after_restart.log.zip (278.3 KB)

20

It looks to me like Sync Gateway is possibly hitting an error when trying to compute revoked documents for the user prior to the restart. This looks to me like a potential bug in how revocation is computed, but there isn’t complete information . It’s not obvious to me why the user doesn’t hit the same bug post-restart, but there is a document write that invalidates the user’s access - it’s possible that’s changing the state of the system post-restart. Regardless, the initial computation failure needs to be reviewed as a potential bug.