Hi. I just wanted to start off by saying thank you ahead of time.
We have 2 different servers with Couchbase Server (4.5.1) and Sync Gateway (1.3.1) installed: staging and production. Our iOS app is using Couchbase Lite 1.3.1. Upon app install, we are able to push and pull changes to both servers. When connected to the staging server, subsequent app opens result in pushing and pulling working as expected. When connected to our production server, subsequent app opens result only pushing working.
What’s really odd is that the app has been working with both servers until around 3/14. Starting then, we received reports that people were having synchronization issues. The issue wasn’t reliably replicable on our end until 3/18.
Using this, NGINX is installed on both servers and configured with the following:
location / {
proxy_pass https://sync_gateway;
proxy_pass_header Accept;
proxy_pass_header Server;
proxy_set_header Upgrade $http_upgrade;
proxy_set_header Connection "upgrade";
proxy_set_header Host $host;
proxy_http_version 1.1;
keepalive_requests 1000;
keepalive_timeout 360s;
proxy_read_timeout 360s;
}
Here are the logs for Sync Gateway on the production server:
11:57:03.395038 HTTP: #18533: GET /pa_test/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545 (as 6047f117b2e7770184f55f6e)
11:57:03.395546 HTTP+: #18533: --> 200 (1.0 ms)
11:57:03.399996 HTTP: #18534: GET /pa_test/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26 (as 6047f117b2e7770184f55f6e)
11:57:03.400189 HTTP+: #18534: --> 200 (0.9 ms)
11:57:03.500481 HTTP: #18535: GET /pa_test/_changes?feed=websocket (as 6047f117b2e7770184f55f6e)
11:57:03.500608 HTTP+: #18535: --> 101 Upgraded to WebSocket protocol (0.0 ms)
and here are the logs for Sync Gateway on the staging server:
11:59:17.834658 HTTP: #344: GET /pa_test/_local/80d4ab9739e24899761651a310bbc43e71273811 (as 5f9aef82073c0d006499497b)
11:59:17.834938 HTTP+: #344: --> 200 (0.6 ms)
11:59:17.837157 HTTP: #345: GET /pa_test/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7 (as 5f9aef82073c0d006499497b)
11:59:17.837441 HTTP+: #345: --> 200 (0.5 ms)
11:59:17.848211 HTTP: #346: POST /pa_test/_revs_diff (as 5f9aef82073c0d006499497b)
11:59:17.848902 HTTP+: #346: --> 200 (0.9 ms)
11:59:17.989716 HTTP: #347: GET /pa_test/_changes?feed=websocket (as 5f9aef82073c0d006499497b)
11:59:17.989856 HTTP+: #347: --> 101 Upgraded to WebSocket protocol (0.0 ms)
11:59:18.060880 Changes+: Int sequence multi changes feed...
11:59:18.060937 Changes: MultiChangesFeed({*}, {Since:566477 Limit:0 Conflicts:true IncludeDocs:false Wait:true Continuous:true Terminator:0xc820bc6d20 HeartbeatMs:300000 TimeoutMs:300000 ActiveOnly:false}) ... (to 5f9aef82073c0d006499497b)
11:59:18.061037 Changes+: MultiChangesFeed: channels expand to channels.TimedSet{"sharedData":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x833ab}, "study:5f9ad582073c0d0064994972":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x833ab}, "!":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x1}, "5f9aef82073c0d006499497b":channels.VbSequence{VbNo:(*uint16)(nil), Sequence:0x833aa}} ... (to 5f9aef82073c0d006499497b)
11:59:18.061056 DIndex+: [changesFeed] Found 0 changes for channel sharedData
11:59:18.061065 DIndex+: [changesFeed] Found 0 changes for channel study:5f9ad582073c0d0064994972
11:59:18.061079 Cache: getCachedChanges("!", {1 0 0 566477 <nil> <nil> %!d(string=) 0 0 0 %!d(string=)}) --> 0 changes valid from #1
11:59:18.061128 DIndex+: [changesFeed] Found 0 changes for channel !
11:59:18.061237 Cache: getCachedChanges("5f9aef82073c0d006499497b", {1 0 0 566477 <nil> <nil> %!d(string=) 0 0 0 %!d(string=)}) --> 1 changes valid from #566478
11:59:18.061248 DIndex+: [changesFeed] Found 1 changes for channel 5f9aef82073c0d006499497b
11:59:18.061282 Changes+: Sending seq:566487 from channel 5f9aef82073c0d006499497b
11:59:18.061339 Changes+: MultiChangesFeed sending &{Seq:566487 ID:-6bYGZg8P_iu7AyLgt81g0j Deleted:false Removed:{} Doc:map[] Changes:[map[rev:1-9a2508cca43a4cab644bf86a011b835d]] Err:<nil> allRemoved:false branched:false} (to 5f9aef82073c0d006499497b)
11:59:18.061350 Changes+: MultiChangesFeed waiting... (to 5f9aef82073c0d006499497b)
11:59:18.061358 Changes+: Waiting for "pa_test"'s count to pass 235
11:59:18.061365 Changes: sending 1 change(s)
The following log types are enabled in the app:
CBLManager.enableLogging("BLIPVerbose")
CBLManager.enableLogging("ChangeTrackerVerbose")
CBLManager.enableLogging("JSONReaderVerbose")
CBLManager.enableLogging("ReachabilityVerbose")
CBLManager.enableLogging("RemoteRequestVerbose")
CBLManager.enableLogging("ServerVerbose")
CBLManager.enableLogging("SyncVerbose")
CBLManager.enableLogging("SyncPerfVerbose")
The main difference I noticed was that CBLWebSocketChangeTracker doesn’t receive a message from the production server but does from the staging server. Here are the app logs for app launches after initial install (production server, pull replication issues):
2021-03-25 10:48:31.754609-0500 Server: CBL_RunLoopServer[0x283362380] Starting server thread ...
2021-03-25 10:48:31.754692-0500 Sync: CBLReplication[from <redacted>]: offline, progress = 0 / 0, err: (null)
2021-03-25 10:48:31.754703-0500 Server: CBL_RunLoopServer[0x283362380]: Server thread starting...
2021-03-25 10:48:31.754778-0500 Sync: CBLReplication[to <redacted>]: offline, progress = 0 / 0, err: (null)
2021-03-25 10:48:31.755751-0500 Sync: CBLRestPuller[<redacted>] STARTING ...
2021-03-25 10:48:31.755808-0500 SyncPerf: CBLRestPuller[<redacted>] STARTING ...
2021-03-25 10:48:31.757596-0500 Reachability: <redacted>:reachable: flags=2; starting...
2021-03-25 10:48:31.757631-0500 Sync: CBLRestPuller[<redacted>]: Reachability state = <redacted>:reachable (02), suspended=0
2021-03-25 10:48:31.757659-0500 Sync: CBLRestPuller[<redacted>]: Going online
2021-03-25 10:48:31.757682-0500 Sync: CBLRestPuller[<redacted>] Progress: set active = 1
2021-03-25 10:48:31.757700-0500 Sync: CBLRestPuller[<redacted>]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
2021-03-25 10:48:31.757750-0500 Sync: CBLRestPuller[<redacted>]: Successfully logged in!
2021-03-25 10:48:31.757846-0500 SyncPerf: CBLRestPuller[<redacted>] Getting remote checkpoint
2021-03-25 10:48:31.758009-0500 Sync: <CBLRemoteSession: 0x28169b700>: GET /pa_test/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26
2021-03-25 10:48:31.758051-0500 RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[6047f117b2e7770184f55f6e/****]
2021-03-25 10:48:31.758081-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]: Starting...
2021-03-25 10:48:31.758144-0500 DEALLOC CBLRemoteLogin[<redacted>]
2021-03-25 10:48:31.758164-0500 RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]
2021-03-25 10:48:31.758177-0500 Sync: CBLRestPuller[<redacted>]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
2021-03-25 10:48:31.758946-0500 Sync: CBLRestPusher[<redacted>] STARTING ...
2021-03-25 10:48:31.759059-0500 SyncPerf: CBLRestPusher[<redacted>] STARTING ...
2021-03-25 10:48:31.760358-0500 Reachability: <redacted>:reachable: flags=2; starting...
2021-03-25 10:48:31.760390-0500 Sync: CBLRestPusher[<redacted>]: Reachability state = <redacted>:reachable (02), suspended=0
2021-03-25 10:48:31.760408-0500 Sync: CBLRestPusher[<redacted>]: Going online
2021-03-25 10:48:31.760425-0500 Sync: CBLRestPusher[<redacted>] Progress: set active = 1
2021-03-25 10:48:31.760440-0500 Sync: CBLRestPusher[<redacted>]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
2021-03-25 10:48:31.760482-0500 Sync: CBLRestPusher[<redacted>]: Successfully logged in!
2021-03-25 10:48:31.760769-0500 Sync: CBLReplication[from <redacted>]: active, progress = 0 / 0, err: (null)
2021-03-25 10:48:31.761885-0500 SyncPerf: CBLRestPusher[<redacted>] Getting remote checkpoint
2021-03-25 10:48:31.762008-0500 Sync: <CBLRemoteSession: 0x2816e44b0>: GET /pa_test/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545
2021-03-25 10:48:31.762241-0500 RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[6047f117b2e7770184f55f6e/****]
2021-03-25 10:48:31.762388-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]: Starting...
2021-03-25 10:48:31.762673-0500 DEALLOC CBLRemoteLogin[<redacted>]
2021-03-25 10:48:31.762698-0500 Sync: CBLRestPusher[<redacted>]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
2021-03-25 10:48:31.762954-0500 RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]
2021-03-25 10:48:31.776829-0500 Sync: CBLReplication[to <redacted>]: active, progress = 0 / 0, err: (null)
2021-03-25 10:48:31.819134-0500 RemoteRequest: Got challenge for CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]: method=NSURLAuthenticationMethodServerTrust, err=(null)
2021-03-25 10:48:31.823651-0500 RemoteRequest: useCredential for trust: <SecTrustRef: 0x2807e0360>
2021-03-25 10:48:31.823706-0500 RemoteRequest: Got challenge for CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]: method=NSURLAuthenticationMethodServerTrust, err=(null)
2021-03-25 10:48:31.825695-0500 RemoteRequest: useCredential for trust: <SecTrustRef: 0x2807e0480>
2021-03-25 10:48:31.849852-0500 Sync: CBLRestPuller[<redacted>]: Server is Couchbase Sync Gateway/1.3.1
2021-03-25 10:48:31.849881-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]: Got response, status 200
2021-03-25 10:48:31.849959-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]: Got 110 bytes
2021-03-25 10:48:31.850005-0500 RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]
2021-03-25 10:48:31.850016-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/1193a31246d9e41c9a72bf3674aaa572b9933e26]: Finished loading
2021-03-25 10:48:31.850066-0500 SyncPerf: CBLRestPuller[<redacted>] Got remote checkpoint
2021-03-25 10:48:31.850146-0500 Sync: CBLRestPuller[<redacted>]: Replicating from lastSequence=10166464
2021-03-25 10:48:31.850243-0500 Sync: CBLRestPuller[<redacted>] starting ChangeTracker: mode=3, since=10166464
2021-03-25 10:48:31.850310-0500 ChangeTracker: CBLWebSocketChangeTracker[0x280acac10 pa_test]: Starting...
2021-03-25 10:48:31.850404-0500 Sync: CBLWebSocketChangeTracker[0x280acac10 pa_test]: GET //redacted:443/pa_test/_changes?feed=websocket
2021-03-25 10:48:31.850934-0500 ChangeTracker: CBLWebSocketChangeTracker[0x280acac10 pa_test]: Started... <<redacted>/_changes?feed=websocket>
2021-03-25 10:48:31.855068-0500 Sync: CBLRestPusher[<redacted>]: Server is Couchbase Sync Gateway/1.3.1
2021-03-25 10:48:31.855099-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]: Got response, status 200
2021-03-25 10:48:31.855158-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]: Got 105 bytes
2021-03-25 10:48:31.855219-0500 RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]
2021-03-25 10:48:31.855222-0500 RemoteRequest: CBLRemoteJSONRequest[GET <redacted>/_local/254547d23d644ffe5dfb99dbd1a8015bebf83545]: Finished loading
2021-03-25 10:48:31.855250-0500 SyncPerf: CBLRestPusher[<redacted>] Got remote checkpoint
2021-03-25 10:48:31.855267-0500 Sync: CBLRestPusher[<redacted>]: Replicating from lastSequence=146
2021-03-25 10:48:31.855398-0500 Sync: CBLRestPusher[<redacted>]: Received 0 revs
2021-03-25 10:48:31.855423-0500 Sync: CBLRestPusher[<redacted>] Progress: set active = 0
2021-03-25 10:48:31.855483-0500 Sync: CBLRestPusher[<redacted>]: postProgressChanged (0/0, active=0 (batch=0, net=0), lastSeq=146, online=1, error=(null))
2021-03-25 10:48:31.855547-0500 SyncPerf: CBLRestPusher[<redacted>] is now inactive
2021-03-25 10:48:31.855656-0500 Sync: CBLReplication[to <redacted>]: idle, progress = 0 / 0, err: (null)
2021-03-25 10:48:32.076776-0500 ChangeTracker: CBLWebSocketChangeTracker[0x280acac10 pa_test]: WebSocket opened
And here are the logs for app launches after initial install (staging server, no issues):
11:05:49.775| Server: CBL_RunLoopServer[0x600000a5c9c0] Starting server thread ...
11:05:49.776| Sync: CBLReplication[from redacted]: offline, progress = 0 / 0, err: (null)
11:05:49.776‖ Server: CBL_RunLoopServer[0x600000a5c9c0]: Server thread starting...
11:05:49.776| Sync: CBLReplication[to redacted]: offline, progress = 0 / 0, err: (null)
11:05:49.778‖ Sync: CBLRestPuller[redacted] STARTING ...
11:05:49.778‖ SyncPerf: CBLRestPuller[redacted] STARTING ...
11:05:49.780‖ Reachability: <redacted>:reachable: flags=2; starting...
11:05:49.780‖ Sync: CBLRestPuller[redacted]: Reachability state = <redacted>:reachable (02), suspended=0
11:05:49.780‖ Sync: CBLRestPuller[redacted]: Going online
11:05:49.781‖ Sync: CBLRestPuller[redacted] Progress: set active = 1
11:05:49.781‖ Sync: CBLRestPuller[redacted]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
11:05:49.781‖ Sync: CBLRestPuller[redacted]: Successfully logged in!
11:05:49.781‖ SyncPerf: CBLRestPuller[redacted] Getting remote checkpoint
11:05:49.782‖ Sync: <CBLRemoteSession: 0x600002fd4aa0>: GET /pa_test/_local/80d4ab9739e24899761651a310bbc43e71273811
11:05:49.782‖ RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[5f9aef82073c0d006499497b/****]
11:05:49.782‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Starting...
11:05:49.782‖ RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]
11:05:49.782‖ DEALLOC CBLRemoteLogin[redacted]
11:05:49.782‖ Sync: CBLRestPuller[redacted]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
11:05:49.783‖ Sync: CBLRestPusher[redacted] STARTING ...
11:05:49.783‖ SyncPerf: CBLRestPusher[redacted] STARTING ...
11:05:49.784‖ Reachability: <redacted>:reachable: flags=2; starting...
11:05:49.784‖ Sync: CBLRestPusher[redacted]: Reachability state = <redacted>:reachable (02), suspended=0
11:05:49.784‖ Sync: CBLRestPusher[redacted]: Going online
11:05:49.784‖ Sync: CBLRestPusher[redacted] Progress: set active = 1
11:05:49.784‖ Sync: CBLRestPusher[redacted]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
11:05:49.785‖ Sync: CBLRestPusher[redacted]: Successfully logged in!
11:05:49.785‖ SyncPerf: CBLRestPusher[redacted] Getting remote checkpoint
11:05:49.785‖ Sync: <CBLRemoteSession: 0x600002fd4c30>: GET /pa_test/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7
11:05:49.785‖ RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[5f9aef82073c0d006499497b/****]
11:05:49.785‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Starting...
11:05:49.785‖ DEALLOC CBLRemoteLogin[redacted]
11:05:49.785‖ RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]
11:05:49.785‖ Sync: CBLRestPusher[redacted]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
11:05:49.798| Sync: CBLReplication[from redacted]: active, progress = 0 / 0, err: (null)
11:05:49.798| Sync: CBLReplication[to redacted]: active, progress = 0 / 0, err: (null)
11:05:49.865‖ RemoteRequest: Got challenge for CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: method=NSURLAuthenticationMethodServerTrust, err=(null)
11:05:49.872‖ RemoteRequest: useCredential for trust: <SecTrustRef: 0x600003e98000>
11:05:49.872‖ RemoteRequest: Got challenge for CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: method=NSURLAuthenticationMethodServerTrust, err=(null)
11:05:49.879‖ RemoteRequest: useCredential for trust: <SecTrustRef: 0x600003e943f0>
11:05:49.947‖ Sync: CBLRestPuller[redacted]: Server is Couchbase Sync Gateway/1.3.1
11:05:49.947‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Got response, status 200
11:05:49.947‖ Sync: CBLRestPusher[redacted]: Server is Couchbase Sync Gateway/1.3.1
11:05:49.947‖ RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]
11:05:49.947‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Got response, status 200
11:05:49.948‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Got 108 bytes
11:05:49.948‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Finished loading
11:05:49.948‖ SyncPerf: CBLRestPuller[redacted] Got remote checkpoint
11:05:49.948‖ RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]
11:05:49.948‖ Sync: CBLRestPuller[redacted]: Replicating from lastSequence=566343
11:05:49.948‖ Sync: CBLRestPuller[redacted] starting ChangeTracker: mode=3, since=566343
11:05:49.949‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: Starting...
11:05:49.949‖ Sync: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: GET //redacted:443/pa_test/_changes?feed=websocket
11:05:49.955‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: Started... <redacted/_changes?feed=websocket>
11:05:49.955‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Got 105 bytes
11:05:49.955‖ RemoteRequest: CBLRemoteJSONRequest[GET redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Finished loading
11:05:49.955‖ SyncPerf: CBLRestPusher[redacted] Got remote checkpoint
11:05:49.955‖ Sync: CBLRestPusher[redacted]: Replicating from lastSequence=213
11:05:49.956‖ Sync: CBLRestPusher[redacted]: Received 0 revs
11:05:49.956‖ Sync: CBLRestPusher[redacted] Progress: set active = 0
11:05:49.956‖ Sync: CBLRestPusher[redacted]: postProgressChanged (0/0, active=0 (batch=0, net=0), lastSeq=213, online=1, error=(null))
11:05:49.956‖ SyncPerf: CBLRestPusher[redacted] is now inactive
11:05:49.956| Sync: CBLReplication[to redacted]: idle, progress = 0 / 0, err: (null)
11:05:50.145‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: WebSocket opened
11:05:50.199‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: Got a message: []
11:05:50.199‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: read 2 bytes
11:05:50.199‖ JSONReader: Start with <CBLTemplateMatcher: 0x600000a594a0>
11:05:50.199‖ JSONReader: Start array
11:05:50.199‖ JSONReader: Pushed <CBLTemplateMatcher: 0x600000bb1a20>
11:05:50.199‖ JSONReader: End array
11:05:50.199‖ JSONReader: Popped: now <CBLTemplateMatcher: 0x600000a594a0>
11:05:50.199‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: caught up!
11:05:50.199‖ Sync: CBLRestPuller[redacted]: Caught up with changes!
11:05:50.199‖ Sync: CBLRestPuller[redacted] Progress: set active = 0
11:05:50.199‖ Sync: CBLRestPuller[redacted]: postProgressChanged (0/0, active=0 (batch=0, net=0), lastSeq=566343, online=1, error=(null))
11:05:50.199‖ SyncPerf: CBLRestPuller[redacted] is now inactive
11:05:50.199| Sync: CBLReplication[from redacted]: idle, progress = 0 / 0, err: (null)
11:05:50.326‖ Sync: CBLRestPusher[redacted]: Queuing #214 {-R5vTw1TvzF-55rZKSAWBYF #1-ac25b462c7a0cdb9cb7eb469c7e98539}
11:05:50.326‖ Sync: CBLRestPusher[redacted] Progress: set active = 1
11:05:50.326‖ Sync: CBLRestPusher[redacted]: postProgressChanged (0/0, active=1 (batch=1, net=0), lastSeq=213, online=1, error=(null))
11:05:50.326‖ Sync: *** CBLRestPusher[redacted]: BEGIN processInbox (1 sequences)
11:05:50.326‖ Sync: <CBLRemoteSession: 0x600002fd4c30>: POST /pa_test/_revs_diff
11:05:50.326‖ RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[5f9aef82073c0d006499497b/****]
11:05:50.326‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_revs_diff]: Starting...
11:05:50.326‖ Sync: *** CBLRestPusher[redacted]: END processInbox (lastSequence=213)
11:05:50.326‖ RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[POST redacted/_revs_diff]
11:05:50.340‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_revs_diff]: Got response, status 200
11:05:50.341‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_revs_diff]: Got 79 bytes
11:05:50.341‖ RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[POST redacted/_revs_diff]
11:05:50.341‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_revs_diff]: Finished loading
11:05:50.341‖ Sync: CBLRestPusher[redacted]: Sending 1 revisions
11:05:50.341‖ Sync: CBLRestPusher[redacted]: Sending (
"{-R5vTw1TvzF-55rZKSAWBYF #1-ac25b462c7a0cdb9cb7eb469c7e98539}"
)
11:05:50.341‖ Sync: CBLRestPusher[redacted]: postProgressChanged (0/1, active=1 (batch=0, net=1), lastSeq=213, online=1, error=(null))
11:05:50.341‖ Sync: <CBLRemoteSession: 0x600002fd4c30>: POST /pa_test/_bulk_docs
11:05:50.341‖ RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[5f9aef82073c0d006499497b/****]
11:05:50.342‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_bulk_docs]: Starting...
11:05:50.342‖ RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[POST redacted/_bulk_docs]
11:05:50.357‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_bulk_docs]: Got response, status 201
11:05:50.358‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_bulk_docs]: Got 97 bytes
11:05:50.358‖ RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[POST redacted/_bulk_docs]
11:05:50.358‖ RemoteRequest: CBLRemoteJSONRequest[POST redacted/_bulk_docs]: Finished loading
11:05:50.358‖ Sync: CBLRestPusher[redacted]: Setting lastSequence to 214 (from 213)
11:05:50.358‖ Sync: CBLRestPusher[redacted]: postProgressChanged (0/1, active=1 (batch=0, net=1), lastSeq=214, online=1, error=(null))
11:05:50.358‖ Sync: CBLRestPusher[redacted]: Sent (
"{-R5vTw1TvzF-55rZKSAWBYF #1-ac25b462c7a0cdb9cb7eb469c7e98539}"
)
11:05:50.358‖ Sync: CBLRestPusher[redacted] Progress: 1 / 1
11:05:50.358‖ Sync: CBLRestPusher[redacted]: postProgressChanged (1/1, active=1 (batch=0, net=1), lastSeq=214, online=1, error=(null))
11:05:50.358‖ Sync: CBLRestPusher[redacted] Progress: set active = 0
11:05:50.358‖ Sync: CBLRestPusher[redacted]: postProgressChanged (1/1, active=0 (batch=0, net=0), lastSeq=214, online=1, error=(null))
11:05:50.358‖ SyncPerf: CBLRestPusher[redacted] is now inactive
11:05:50.422| Sync: CBLReplication[to redacted]: active, progress = 0 / 0, err: (null)
11:05:50.422| Sync: CBLReplication[to redacted]: active, progress = 0 / 1, err: (null)
11:05:50.422| Sync: CBLReplication[to redacted]: idle, progress = 1 / 1, err: (null)
11:05:51.686‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: Got a message: {length = 117, bytes = 0x1f8b0800 00096e88 00ff8aae 562a4e2d ... 6b630100 0000ffff }
11:05:51.686‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: read 104 bytes
11:05:51.686‖ JSONReader: Start with <CBLTemplateMatcher: 0x600000bb49c0>
11:05:51.686‖ JSONReader: Start array
11:05:51.686‖ JSONReader: Pushed <CBLTemplateMatcher: 0x600000bb4420>
11:05:51.686‖ JSONReader: Start object
11:05:51.686‖ JSONReader: Pushed <CBLChangeMatcher: 0x6000019442c0>
11:05:51.686‖ JSONReader: Object key: "seq"
11:05:51.686‖ JSONReader: Match 566477
11:05:51.686‖ JSONReader: Object key: "id"
11:05:51.686‖ JSONReader: Match "-R5vTw1TvzF-55rZKSAWBYF"
11:05:51.686‖ JSONReader: Object key: "changes"
11:05:51.686‖ JSONReader: Start array
11:05:51.686‖ JSONReader: Pushed <CBLTemplateMatcher: 0x600000bb45c0>
11:05:51.686‖ JSONReader: Start object
11:05:51.686‖ JSONReader: Pushed <CBLRevInfoMatcher: 0x600000bb4220>
11:05:51.686‖ JSONReader: Object key: "rev"
11:05:51.686‖ JSONReader: Match "1-ac25b462c7a0cdb9cb7eb469c7e98539"
11:05:51.686‖ JSONReader: End object
11:05:51.686‖ JSONReader: Popped: now <CBLTemplateMatcher: 0x600000bb45c0>
11:05:51.686‖ JSONReader: End array
11:05:51.686‖ JSONReader: Popped: now <CBLChangeMatcher: 0x6000019442c0>
11:05:51.686‖ JSONReader: End object
11:05:51.687‖ Sync: CBLRestPuller[redacted]: postProgressChanged (0/1, active=0 (batch=0, net=0), lastSeq=566343, online=1, error=(null))
11:05:51.687‖ Sync: CBLRestPuller[redacted]: Received #566477 {-R5vTw1TvzF-55rZKSAWBYF #1-ac25b462c7a0cdb9cb7eb469c7e98539}
11:05:51.687‖ Sync: CBLRestPuller[redacted] Progress: set active = 1
11:05:51.687‖ Sync: CBLRestPuller[redacted]: postProgressChanged (0/1, active=1 (batch=1, net=0), lastSeq=566343, online=1, error=(null))
11:05:51.692‖ JSONReader: Popped: now <CBLTemplateMatcher: 0x600000bb4420>
11:05:51.693‖ JSONReader: End array
11:05:51.693‖ JSONReader: Popped: now <CBLTemplateMatcher: 0x600000bb49c0>
11:05:51.693‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: RESUME WebSocket
11:05:51.693‖ ChangeTracker: CBLWebSocketChangeTracker[0x6000033b3750 pa_test]: Got a message:
11:05:51.693‖ Sync: *** CBLRestPuller[redacted]: BEGIN processInbox (1 sequences)
11:05:51.693| Sync: CBLReplication[from redacted]: active, progress = 0 / 1, err: (null)
11:05:51.693‖ SyncPerf: CBLRestPuller[redacted]: Processing 1 changes
11:05:51.693‖ Sync: CBLRestPuller[redacted]: Looking up (
"{-R5vTw1TvzF-55rZKSAWBYF #1-ac25b462c7a0cdb9cb7eb469c7e98539}"
)
11:05:51.693‖ Sync: CBLRestPuller[redacted] Progress: 1 / 1
11:05:51.693‖ Sync: CBLRestPuller[redacted]: postProgressChanged (1/1, active=1 (batch=0, net=0), lastSeq=566343, online=1, error=(null))
11:05:51.693‖ Sync: CBLRestPuller[redacted]: no new remote revisions to fetch
11:05:51.693‖ Sync: CBLRestPuller[redacted]: Setting lastSequence to 566477 (from 566343)
11:05:51.693‖ Sync: CBLRestPuller[redacted]: postProgressChanged (1/1, active=1 (batch=0, net=0), lastSeq=566477, online=1, error=(null))
11:05:51.693‖ Sync: *** CBLRestPuller[redacted]: END processInbox (lastSequence=566477)
11:05:51.693‖ Sync: CBLRestPuller[redacted] Progress: set active = 0
11:05:51.693‖ Sync: CBLRestPuller[redacted]: postProgressChanged (1/1, active=0 (batch=0, net=0), lastSeq=566477, online=1, error=(null))
11:05:51.693‖ SyncPerf: CBLRestPuller[redacted] is now inactive
11:05:51.693| Sync: CBLReplication[from redacted]: idle, progress = 1 / 1, err: (null)
11:05:55.363‖ Sync: CBLRestPusher[redacted] checkpointing sequence=214
11:05:55.363‖ Sync: <CBLRemoteSession: 0x600002fd4c30>: PUT /pa_test/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7
11:05:55.363‖ RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[5f9aef82073c0d006499497b/****]
11:05:55.363‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Starting...
11:05:55.363‖ RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[PUT redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]
11:05:55.380‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Got response, status 201
11:05:55.381‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Got 92 bytes
11:05:55.381‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]: Finished loading
11:05:55.381‖ RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[PUT redacted/_local/ab2c0f1b5313b3069b340a43fd8f63b634bdc8f7]
11:05:55.381‖ Sync: CBLRestPusher[redacted] saved remote checkpoint '214' (_rev=0-8)
11:05:56.696‖ Sync: CBLRestPuller[redacted] checkpointing sequence=566477
11:05:56.696‖ Sync: <CBLRemoteSession: 0x600002fd4aa0>: PUT /pa_test/_local/80d4ab9739e24899761651a310bbc43e71273811
11:05:56.696‖ RemoteRequest: Added Authorization header for CBLPasswordAuthorizer[5f9aef82073c0d006499497b/****]
11:05:56.696‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Starting...
11:05:56.697‖ RemoteRequest: CBLRemoteSession starting CBLRemoteJSONRequest[PUT redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]
11:05:56.708‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Got response, status 201
11:05:56.708‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Got 92 bytes
11:05:56.708‖ RemoteRequest: CBLRemoteSession done with CBLRemoteJSONRequest[PUT redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]
11:05:56.708‖ RemoteRequest: CBLRemoteJSONRequest[PUT redacted/_local/80d4ab9739e24899761651a310bbc43e71273811]: Finished loading
11:05:56.708‖ Sync: CBLRestPuller[redacted] saved remote checkpoint '566477' (_rev=0-8)