App needs trigger(going back to home screen and realunch) to sync/pull docs

[ashvindersingh]

Steps to reproduce:

• Setup ToDo lite iOS
• Setup a SG with latest release: 1.2.0-69
• Ensure replication works fine by push and pull some docs
• Take db offline ( http://sg_url:4985/_offline )
• Create docs/Lists on another device/endpoint with tasks while db is in offline mode
• Bring db online ( http://sg_url:4985/_online )

Observe:
Device under test App doesn't pull docs automatically. Only after home button is pressed and App is again launched it pulls all docs.

• related with https://github.com/couchbase/couchbase-lite-java-core/issues/963
• Background: App needs trigger(going back to home screen and realunch) to sync/pull docs couchbaselabs/ToDoLite-iOS#61
• logs: https://gist.github.com/ashvindersingh/893f0d8395bd55bc4d35

[pasin]

@ashvindersingh I couldn't reproduce the issue. ChangeTracker sometimes waits for several seconds (wait time increases exponentially) before retrying. Could you add the following loggings databaseForName:(NSString *)name method in AppDelegate.m and reproduce the issue?

If possible, please delete the existing [CBLManager enableLogging:@"CBLDatabase"] to reduce noise in the log.

[CBLManager enableLogging:@"Sync"];
[CBLManager enableLogging:@"SyncVerbose"];
[CBLManager enableLogging:@"ChangeTracker"];
[CBLManager enableLogging:@"ChangeTrackerVerbose"];

[ashvindersingh]

@pasin I will try without enableLogging

[pasin]

Please enable the following:

[CBLManager enableLogging:@"Sync"];
[CBLManager enableLogging:@"SyncVerbose"];
[CBLManager enableLogging:@"ChangeTracker"];
[CBLManager enableLogging:@"ChangeTrackerVerbose"];

[pasin]

@ashvindersingh do you have any updates on this?

[ashvindersingh]

Please try with
#define kSyncGatewayWebSocketSupport YES in the AppDelegate.m of ToDoliteApp

[snej]

I didn't know that ToDoLite disables WebSockets by default. So that means our testathon last week wasn't testing WebSocket-based changes feeds :(

[ashvindersingh]

Actually three of us had this enabled: @michaelkwok , @suravarjjala and myself. We had our todoLite with settings:

• ForestDB w Encryption
• Websockets enabled.

[pasin]

I was able to reproduce. WebSocket Change Tracker stopped without error right after bringing the SyncGateway offline.

2016-02-01 15:28:38.735 ToDoLite[424:81209] ChangeTracker: CBLWebSocketChangeTracker[0x135e70680 todos]: closed
2016-02-01 15:28:38.736 ToDoLite[424:81209] Sync: CBLRestPuller[http://10.17.2.133:4984/todos]: ChangeTracker stopped; error=(null)

[pasin]

This is weird as I couldn't reproduce the same behavior with the unit test.

16:00:10.428‖ CBLWebSocketChangeTracker[0x6110000f6e40 cbl_replicator_pushpull]: Connection error #1, retrying in 2.0 sec: Output stream end encountered
16:00:12.430‖ ChangeTracker: CBLWebSocketChangeTracker[0x6110000f6e40 cbl_replicator_pushpull]: Starting...
16:00:12.430‖ SyncVerbose: CBLWebSocketChangeTracker[0x6110000f6e40 cbl_replicator_pushpull]: GET //localhost:4994/cbl_replicator_pushpull/_changes?feed=websocket
16:00:12.431‖ ChangeTracker: CBLWebSocketChangeTracker[0x6110000f6e40 cbl_replicator_pushpull]: Started... <https://localhost:4994/cbl_replicator_pushpull/_changes?feed=websocket>
16:00:12.445‖ CBLWebSocketChangeTracker[0x6110000f6e40 cbl_replicator_pushpull]: Connection error #2, retrying in 4.0 sec: HTTP/1.1 503 Service Unavailable
16:00:16.445‖ ChangeTracker: CBLWebSocketChangeTracker[0x6110000f6e40 cbl_replicator_pushpull]: Starting...

[pasin]

OK, the same behavior can be reproduced only when the sync-gateway URL is non-SSL.

From SyncGateway log when URL is http://xxx

2016-02-01T16:10:32.201-08:00 HTTP:  #014: PUT /cbl_replicator_pushpull/_local/9590c456ceb7d0a48156a0982a3062e2752df122
2016-02-01T16:10:32.201-08:00 HTTP+: #014:     --> 201   (0.3 ms)
2016-02-01T16:10:39.119-08:00 HTTP:  #015: POST /cbl_replicator_pushpull/_offline  (ADMIN)
2016-02-01T16:10:39.119-08:00 HTTP+: #009:     --> 200 OK DB has gone offline  (0.0 ms)
2016-02-01T16:10:39.119-08:00 HTTP+: #013:     --> WebSocket closed
2016-02-01T16:10:39.119-08:00 HTTP+: #015:     --> 200   (0.2 ms)

[pasin]

Look like the bug is down at the PocketSocket library that when the URL is non-ssl, the websocket is closed without an error when bringing the SyncGateway offline.

[pasin]

I debugged into the PocketSocket library and found that the WebSocket closed with '1000' status code (1000 = Normal closure). However when the remote URL is https, there is an error event stream happens right after while the closing socket is waiting for processing on a dispatch queue.

At this point, I think it might be that SyncGateway may need to send a status code that can indicate WebSocket error (https://developer.mozilla.org/en-US/docs/Web/API/CloseEvent) so that the WebSocket library can handle that properly.

[snej]

Even if the server closes the connection cleanly/normally, the change-tracker should still treat it as a (recoverable) error and retry. A WebSocket changes feed isn't supposed to close.
The PR I just filed converts the normal status to a 503 (Service Unavailable) which will trigger a retry.

[ajaykoppisetty]

I was seeing this issue only my test environment, not on development. I have enabled the log and posted here. (Both the environments using http not https) Seems like the CBLWebSocketChangeTracker is receiving the message but the CBLReplication is still in idle state and not pulling the doc until going back to home screen and realunch the app.

2017-12-20 16:41:02.522881+0530 MyApp[57504:6969061] [MC] System group container for systemgroup.com.apple.configurationprofiles path is /Users/aj/Library/Developer/CoreSimulator/Devices/B5226716-810A-4A58-A82A-2E0438100BA8/data/Containers/Shared/SystemGroup/systemgroup.com.apple.configurationprofiles
2017-12-20 16:41:02.523713+0530 MyApp[57504:6969061] [MC] Reading from private effective user settings.
16:41:02.530‖ SQLite message: recovered 19 frames from WAL file /Users/aj/Library/Developer/CoreSimulator/Devices/B5226716-810A-4A58-A82A-2E0438100BA8/data/Containers/Data/Application/84A6B4BD-B0F6-4B36-82A0-374871E5CC03/Library/Caches/com.myapp.barrick.operator/Cache.db-wal
16:41:02.538| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: offline, progress = 0 / 0, err: (null)
16:41:02.541‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] STARTING ...
16:41:02.543| Sync: CBLReplication[from http://syncgateway_url:4944/test-script]: offline, progress = 0 / 0, err: (null)
16:41:02.544‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Reachability state = <syncgateway_url>:reachable (02), suspended=0
16:41:02.544‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Going online
16:41:02.544‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] Progress: set active = 1
16:41:02.544‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
16:41:02.544‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Successfully logged in!
16:41:02.545‖ Sync: <CBLRemoteSession: 0x60000009a5e0>: GET /test-script/_local/8ec664a9942a235d12bbdafa8ccbdbdfe966ffc7
16:41:02.545‖ DEALLOC CBLRemoteLogin[http://syncgateway_url:4944/test-script]
16:41:02.559‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
16:41:02.560‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] STARTING ...
16:41:02.562‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Reachability state = <syncgateway_url>:reachable (02), suspended=0
16:41:02.562‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Going online
16:41:02.562‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] Progress: set active = 1
16:41:02.562‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
16:41:02.562‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Successfully logged in!
16:41:02.562‖ Sync: <CBLRemoteSession: 0x608000095bd0>: GET /test-script/_local/81a85a9988146df59320b0d57fb09eb58dd1a315
16:41:02.563‖ DEALLOC CBLRemoteLogin[http://syncgateway_url:4944/test-script]
16:41:02.563‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (0/0, active=1 (batch=0, net=1), lastSeq=(null), online=1, error=(null))
Simultaneous accesses to 0x10d26c6a8, but modification requires exclusive access.
Previous access (a modification) started at MyApp`AppDelegate.registerProvisionObserver() + 459 (0x10cdb34bb).
Current access (a modification) started at:
0 libswiftCore.dylib 0x000000011357ef00 swift_beginAccess + 505
1 MyApp 0x000000010cd77840 DataModel.registerObserver(type:ObservingClass:Selector:Context:) + 1755
2 MyApp 0x000000010cdb32f0 AppDelegate.registerProvisionObserver() + 518
3 MyApp 0x000000010d0cc010 NoProvisionInfoVC.viewDidLoad() + 176
4 MyApp 0x000000010d0cc110 @objc NoProvisionInfoVC.viewDidLoad() + 36
5 UIKit 0x000000010f4b0f99 -[UIViewController loadViewIfRequired] + 1235
6 UIKit 0x000000010f4b189e -[UIViewController view] + 27
7 UIKit 0x000000010f4863f3 -[UIPresentationController __sizeClassPair] + 62
8 UIKit 0x000000010f4c3c87 -[UIViewController _presentViewController:withAnimationController:completion:] + 2353
9 UIKit 0x000000010f4c7946 __63-[UIViewController _presentViewController:animated:completion:]block_invoke + 99
10 UIKit 0x000000010f4c7e65 -[UIViewController performCoordinatedPresentOrDismiss:animated:] + 532
11 UIKit 0x000000010f4c7853 -[UIViewController presentViewController:animated:completion:] + 181
12 UIKit 0x000000010f4c7bc8 -[UIViewController presentViewController:animated:completion:] + 159
13 UIKit 0x000000012c184216 -[UIViewControllerAccessibility presentViewController:animated:completion:] + 237
14 MyApp 0x000000010ce36e00 static CommonMethods.showAlertView(:title:controller:) + 893
15 MyApp 0x000000010ce7ee50 NavigationManager.restoreLastSavedState() + 2473
16 MyApp 0x000000010cdafdc0 AppDelegate.application(:didFinishLaunchingWithOptions:) + 300
17 MyApp 0x000000010cdaffb0 @objc AppDelegate.application(:didFinishLaunchingWithOptions:) + 186
18 UIKit 0x000000010f300a9f -[UIApplication _handleDelegateCallbacksWithOptions:isSuspended:restoreState:] + 299
19 UIKit 0x000000010f301637 -[UIApplication _callInitializationDelegatesForMainScene:transitionContext:] + 4113
20 UIKit 0x000000010f307433 -[UIApplication _runWithMainScene:transitionContext:completion:] + 1720
21 UIKit 0x000000010f6d135c __111-[__UICanvasLifecycleMonitor_Compatability _scheduleFirstCommitForScene:transition:firstActivation:completion:]_block_invoke + 924
22 UIKit 0x000000010faa742f +[_UICanvas _enqueuePostSettingUpdateTransactionBlock:] + 153
23 UIKit 0x000000010f6d11f8 -[__UICanvasLifecycleMonitor_Compatability _scheduleFirstCommitForScene:transition:firstActivation:completion:] + 249
24 UIKit 0x000000010f6d18b3 -[__UICanvasLifecycleMonitor_Compatability activateEventsOnly:withContext:completion:] + 696
25 UIKit 0x000000011004f963 __82-[_UIApplicationCanvas _transitionLifecycleStateWithTransitionContext:completion:]_block_invoke + 262
26 UIKit 0x000000011004f766 -[_UIApplicationCanvas _transitionLifecycleStateWithTransitionContext:completion:] + 444
27 UIKit 0x000000010fd2c8eb __125-[_UICanvasLifecycleSettingsDiffAction performActionsForCanvas:withUpdatedScene:settingsDiff:fromSettings:transitionContext:]_block_invoke + 221
28 UIKit 0x000000010ff2baa2 _performActionsWithDelayForTransitionContext + 100
29 UIKit 0x000000010fd2c7a4 -[_UICanvasLifecycleSettingsDiffAction performActionsForCanvas:withUpdatedScene:settingsDiff:fromSettings:transitionContext:] + 231
30 UIKit 0x000000010faa699d -[_UICanvas scene:didUpdateWithDiff:transitionContext:completion:] + 392
31 UIKit 0x000000010f30615f -[UIApplication workspace:didCreateScene:withTransitionContext:completion:] + 523
32 UIKit 0x000000010f8e1494 -[UIApplicationSceneClientAgent scene:didInitializeWithEvent:completion:] + 369
33 FrontBoardServices 0x0000000117fe2b6e -[FBSSceneImpl _didCreateWithTransitionContext:completion:] + 338
34 FrontBoardServices 0x0000000117feb6ca __56-[FBSWorkspace client:handleCreateScene:withCompletion:]_block_invoke_2 + 235
35 libdispatch.dylib 0x0000000114353335 _dispatch_client_callout + 8
36 libdispatch.dylib 0x00000001143587a3 _dispatch_block_invoke_direct + 592
37 FrontBoardServices 0x0000000118017480 FBSSERIALQUEUE_IS_CALLING_OUT_TO_A_BLOCK + 24
38 FrontBoardServices 0x0000000118016f7e -[FBSSerialQueue _performNext] + 464
39 FrontBoardServices 0x0000000118017690 -[FBSSerialQueue _performNextFromRunLoopSource] + 45
40 CoreFoundation 0x00000001123d80f0 CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION + 17
41 CoreFoundation 0x0000000112477f20 __CFRunLoopDoSource0 + 81
42 CoreFoundation 0x00000001123bc960 __CFRunLoopDoSources0 + 185
43 CoreFoundation 0x00000001123bbb00 __CFRunLoopRun + 1279
44 CoreFoundation 0x00000001123bb6f0 CFRunLoopRunSpecific + 409
45 GraphicsServices 0x00000001166cc988 GSEventRunModal + 62
46 UIKit 0x000000010f309537 UIApplicationMain + 159
47 MyApp 0x000000010cdb8f70 main + 55
48 libdyld.dylib 0x00000001143cfd80 start + 1
2017-12-20 16:41:02.810954+0530 MyApp[57504:6969061] Warning: Attempt to present <UIAlertController: 0x7fbe78804e00> on <MyApp.NoProvisionInfoVC: 0x7fbe74f493c0> whose view is not in the window hierarchy!
16:41:02.903| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: active, progress = 0 / 0, err: (null)
16:41:02.904| Sync: CBLReplication[from http://syncgateway_url:4944/test-script]: active, progress = 0 / 0, err: (null)
16:41:02.977| CBLQueryBuilder: Creating new view 'builder-lddYM7+mKFO5ISzHkox48n2kFso='
2017-12-20 16:41:03.032689+0530 MyApp[57504:6969061] [MC] Lazy loading NSBundle MobileCoreServices.framework
2017-12-20 16:41:03.032835+0530 MyApp[57504:6969061] [MC] Loaded MobileCoreServices.framework
16:41:04.389‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Server is Couchbase Sync Gateway/1.3.1
16:41:04.389‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Replicating from lastSequence=7814
16:41:04.391‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Received 1 revs
16:41:04.391‖ Sync: *** CBLRestPusher[http://syncgateway_url:4944/test-script]: BEGIN processInbox (1 sequences)
16:41:04.391‖ Sync: <CBLRemoteSession: 0x60000009a5e0>: POST /test-script/_revs_diff
16:41:04.392‖ Sync: *** CBLRestPusher[http://syncgateway_url:4944/test-script]: END processInbox (lastSequence=7814)
16:41:04.438‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Server is Couchbase Sync Gateway/1.3.1
16:41:04.438‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Replicating from lastSequence=8395287:33060
16:41:04.439‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] starting ChangeTracker: mode=3, since=8395287:33060
16:41:04.439‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: Starting...
16:41:04.441‖ Sync: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: GET //syncgateway_url:4944/test-script/_changes?feed=websocket
16:41:04.441‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: GET //syncgateway_url:4944/test-script/_changes?feed=websocket {
Authorization = "Basic YWRtaW46RzBsZGJAckJAcnJJY2s=";
Host = "syncgateway_url:4944";
"User-Agent" = "CouchbaseLite/1.3 (iOS 1.3.1)";
}
16:41:04.442‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: Started... http://syncgateway_url:4944/test-script/_changes?feed=websocket
16:41:05.252‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Sending 1 revisions
16:41:05.252‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Sending (
"{BLT0002:lastSync #41-4a923dbab6c59c3543a80818d282cfda}"
)
16:41:05.252‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (0/1, active=1 (batch=0, net=1), lastSeq=7814, online=1, error=(null))
16:41:05.253‖ Sync: <CBLRemoteSession: 0x60000009a5e0>: POST /test-script/_bulk_docs
16:41:05.253| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: active, progress = 0 / 1, err: (null)
16:41:05.632‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Setting lastSequence to 7815 (from 7814)
16:41:05.632‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (0/1, active=1 (batch=0, net=1), lastSeq=7815, online=1, error=(null))
16:41:05.632‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Sent (
"{BLT0002:lastSync #41-4a923dbab6c59c3543a80818d282cfda}"
)
16:41:05.632‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] Progress: 1 / 1
16:41:05.633‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (1/1, active=1 (batch=0, net=1), lastSeq=7815, online=1, error=(null))
16:41:05.633‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] Progress: going inactive, after saving checkpoint...
16:41:05.633‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] checkpointing sequence=7815
16:41:05.633‖ Sync: <CBLRemoteSession: 0x60000009a5e0>: PUT /test-script/_local/8ec664a9942a235d12bbdafa8ccbdbdfe966ffc7
16:41:05.636| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: active, progress = 1 / 1, err: (null)
16:41:05.639‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: WebSocket opened
16:41:05.925‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] saved remote checkpoint '7815' (_rev=0-31)
16:41:05.925‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] Progress: set active = 0
16:41:05.925‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (1/1, active=0 (batch=0, net=0), lastSeq=7815, online=1, error=(null))
16:41:05.925| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: idle, progress = 1 / 1, err: (null)
16:41:06.688‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: Got a message: <1f8b0800 00096e88 00ff6c92 bd8a1d31 0c46df65 ea35587f 96755f25 6c21c972 9226902c a409fbee f12d1666 4960aae1 48fa74ac 2f7faeb7 fa793dae 492638f5 41d4075e 2fd7f775 7e12508c 50a01e88 281d72ef 12b0b1aa 7c4b1e2e bff98faf f5763d4e a75ff5fb d9a93705 01de8964 8b5769d6 ee0b1c23 2cc46bcb f5fef241 e36c959e acaba218 c955c56a ba2ba438 42df75a3 891bad1a 40439578 410473c5 02dc71fa f3a9881b 0d448d61 696ed56e 42108370 d374d833 d3fbd671 8f02cccd d6eacfec c135ba9c 9aea33ca bcca527a 8e3b8ebd 81151229 8e183e31 79d1a2dc 61e0064a 7dddf081 cd03d534 5833f731 719c0891 2c8f1349 68ccbb16 69544e96 6ce50ba7 18d85910 962c3def 60c7c0a7 e46d68c7 3575b367 a9a7cf44 ecdcb1dc 142afa9d 1669b3cb f98cce04 4acd3930 06b0a3e9 1847ec27 9c678bd2 e5b2c79e 826784f6 a5decdc5 fa1867db bcde5f9f 05ff9e12 7f9c9231 4aacd074 e974f219 9bf19893 31631de9 ff3d251c 8d1dce26 0ee089e1 5e6168a5 4763cede 15ec39f9 f52f0000 00ffff>
16:41:06.688‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: read 710 bytes
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (0/11, active=1 (batch=0, net=1), lastSeq=8395287:33060, online=1, error=(null))
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #80-71514fc239d4de7cef0d1a2bb9b5aef5}
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #28-ecac47debe423a7759e8aa71c5a210fe}
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #34-3de61367734d1bb44ebd12fb1a24c5ab}
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #133-41d7cf7709531b632f38a1f8cca0f765}
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #144-9dd0514fb4e605953e08be9aee9c50c6}
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #120-19e233726b6a82c4d3d3cfb91a91730d}
16:41:06.689‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #62-ab2797b47ccf9b50d15335dab38a5368}
16:41:06.690‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #25-3ea39c49ead285919a241d5d75019136}
16:41:06.690‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #14-6702d87f4ace7aca8c220402ea971eb0}
16:41:06.690‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #155-8058059339c3c7c862b614a2976634d0}
16:41:06.690‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33062 {313b6b7130b222501cffe5196deeaf5c #148-be7da5f6f852f4a70d7a09a59066b91c}
16:41:06.690‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (0/12, active=1 (batch=11, net=1), lastSeq=8395287:33060, online=1, error=(null))
16:41:06.690‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33064 {9425bdb7ca503aca9499468842cbddd0 #26-4a1c22a11ac2baaeb929e7797c800719}
16:41:06.690‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: RESUME WebSocket
16:41:06.690| Sync: CBLReplication[from http://syncgateway_url:4944/test-script]: active, progress = 0 / 12, err: (null)
16:41:06.690‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: Got a message: <c29a8acd 60563bf9 84181818 1859e524 16970457 e6614fb5 268640ab 2c8d8c53 921293cc 924d81c1 626a629c 68616061 68010c7e a3e4b494 44e47468 a96b6466 6460649a 96646e00 8c39a0b5 e696c0c4 9802cc3c a98669c6 a996c6c8 41027516 d43df1a5 c5a945fa 8929b999 79284e01 7a040000 00ffff>
16:41:06.691‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: read 201 bytes
16:41:06.691‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (0/14, active=1 (batch=12, net=1), lastSeq=8395287:33060, online=1, error=(null))
16:41:06.691‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33066 {BLT0002:lastSync #41-4a923dbab6c59c3543a80818d282cfda}
16:41:06.691‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Received #8395287:33066 {BLT0002:lastSync #39-262025fb7036839579bb4d062e1f3e93}
16:41:06.691‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: RESUME WebSocket
16:41:06.691‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: Got a message: []
16:41:06.691‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: read 2 bytes
16:41:06.691‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: caught up!
16:41:06.691‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Caught up with changes!
16:41:06.691‖ Sync: *** CBLRestPuller[http://syncgateway_url:4944/test-script]: BEGIN processInbox (14 sequences)
16:41:06.692‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Looking up (
"{313b6b7130b222501cffe5196deeaf5c #80-71514fc239d4de7cef0d1a2bb9b5aef5}",
"{313b6b7130b222501cffe5196deeaf5c #28-ecac47debe423a7759e8aa71c5a210fe}",
"{313b6b7130b222501cffe5196deeaf5c #34-3de61367734d1bb44ebd12fb1a24c5ab}",
"{313b6b7130b222501cffe5196deeaf5c #133-41d7cf7709531b632f38a1f8cca0f765}",
"{313b6b7130b222501cffe5196deeaf5c #144-9dd0514fb4e605953e08be9aee9c50c6}",
"{313b6b7130b222501cffe5196deeaf5c #120-19e233726b6a82c4d3d3cfb91a91730d}",
"{313b6b7130b222501cffe5196deeaf5c #62-ab2797b47ccf9b50d15335dab38a5368}",
"{313b6b7130b222501cffe5196deeaf5c #25-3ea39c49ead285919a241d5d75019136}",
"{313b6b7130b222501cffe5196deeaf5c #14-6702d87f4ace7aca8c220402ea971eb0}",
"{313b6b7130b222501cffe5196deeaf5c #155-8058059339c3c7c862b614a2976634d0}",
"{313b6b7130b222501cffe5196deeaf5c #148-be7da5f6f852f4a70d7a09a59066b91c}",
"{9425bdb7ca503aca9499468842cbddd0 #26-4a1c22a11ac2baaeb929e7797c800719}",
"{BLT0002:lastSync #41-4a923dbab6c59c3543a80818d282cfda}",
"{BLT0002:lastSync #39-262025fb7036839579bb4d062e1f3e93}"
)
16:41:06.693‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (12/14, active=1 (batch=0, net=0), lastSeq=8395287:33060, online=1, error=(null))
16:41:06.693‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] queuing remote revisions (
"{313b6b7130b222501cffe5196deeaf5c #80-71514fc239d4de7cef0d1a2bb9b5aef5}",
"{9425bdb7ca503aca9499468842cbddd0 #26-4a1c22a11ac2baaeb929e7797c800719}"
)
16:41:06.693‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] queued 2 remote revisions from seq=8395287:33062 (2 in bulk, 0 individually)
16:41:06.693‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] bulk-fetching 2 remote revisions...
16:41:06.694‖ Sync: CBLBulkDownloader[(null)]: POST _bulk_get?revs=true&attachments=true [{"id":"313b6b7130b222501cffe5196deeaf5c","rev":"80-71514fc239d4de7cef0d1a2bb9b5aef5","atts_since":["79-939dd97b2dade105dab8dd9b6d75e4d3","62-ab2797b47ccf9b50d15335dab38a5368","34-3de61367734d1bb44ebd12fb1a24c5ab","28-ecac47debe423a7759e8aa71c5a210fe","25-3ea39c49ead285919a241d5d75019136","14-6702d87f4ace7aca8c220402ea971eb0"]},{"id":"9425bdb7ca503aca9499468842cbddd0","rev":"26-4a1c22a11ac2baaeb929e7797c800719","atts_since":["24-76ff2f2e5ed6b500699c18c21c8152d4"]}]
16:41:06.695‖ Sync: *** CBLRestPuller[http://syncgateway_url:4944/test-script]: END processInbox (lastSequence=8395287:33060)
16:41:06.695| Sync: CBLReplication[from http://syncgateway_url:4944/test-script]: active, progress = 12 / 14, err: (null)
16:41:07.066‖ Sync: CBLBulkDownloader[/test-script/_bulk_get]: Starting new document; ID="(null)"
16:41:07.066‖ Sync: CBLBulkDownloader[/test-script/_bulk_get]: Finished document
16:41:07.066‖ Sync: CBLMultipartDocumentReader[_id="(null)"]: Finished loading (0 attachments)
16:41:07.067‖ Sync: CBLBulkDownloader[/test-script/_bulk_get]: Starting new document; ID="(null)"
16:41:07.067‖ Sync: CBLBulkDownloader[/test-script/_bulk_get]: Finished document
16:41:07.067‖ Sync: CBLMultipartDocumentReader[_id="(null)"]: Finished loading (0 attachments)
16:41:07.067‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (12/14, active=1 (batch=0, net=3), lastSeq=8395287:33060, online=1, error=(null))
16:41:07.067‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] inserting 2 revisions...
16:41:07.067‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] inserting 313b6b7130b222501cffe5196deeaf5c [80-71514fc239d4de7cef0d1a2bb9b5aef5, 79-939dd97b2dade105dab8dd9b6d75e4d3]
16:41:07.068‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] inserting 9425bdb7ca503aca9499468842cbddd0 [26-4a1c22a11ac2baaeb929e7797c800719, 25-341c27465face226e04619b0ed7d779c, 24-76ff2f2e5ed6b500699c18c21c8152d4]
16:41:07.091‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] finished inserting 2 revisions
16:41:07.091‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Setting lastSequence to 7816 (from 7815)
16:41:07.091‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (1/1, active=0 (batch=0, net=0), lastSeq=7816, online=1, error=(null))
16:41:07.092‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: Setting lastSequence to 7818 (from 7816)
16:41:07.092‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (1/1, active=0 (batch=0, net=0), lastSeq=7818, online=1, error=(null))
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: Setting lastSequence to 8395287:33064 (from 8395287:33060)
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (12/14, active=1 (batch=0, net=2), lastSeq=8395287:33064, online=1, error=(null))
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] inserted 2 revs in 0.025 sec (80.1/sec)
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] Progress: going inactive, after saving checkpoint...
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] checkpointing sequence=8395287:33064
16:41:07.092‖ Sync: <CBLRemoteSession: 0x608000095bd0>: PUT /test-script/_local/81a85a9988146df59320b0d57fb09eb58dd1a315
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] Progress: 14 / 14
16:41:07.092‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (14/14, active=1 (batch=0, net=1), lastSeq=8395287:33064, online=1, error=(null))
16:41:07.093| Sync: CBLReplication[from http://syncgateway_url:4944/test-script]: active, progress = 14 / 14, err: (null)
16:41:07.671‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] saved remote checkpoint '8395287:33064' (_rev=0-9)
16:41:07.671‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script] Progress: set active = 0
16:41:07.671‖ Sync: CBLRestPuller[http://syncgateway_url:4944/test-script]: postProgressChanged (14/14, active=0 (batch=0, net=0), lastSeq=8395287:33064, online=1, error=(null))
16:41:07.671| Sync: CBLReplication[from http://syncgateway_url:4944/test-script]: idle, progress = 14 / 14, err: (null)
16:41:10.637‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] checkpointing sequence=7818
16:41:10.637‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] Progress: set active = 1
16:41:10.638‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (1/1, active=1 (batch=0, net=1), lastSeq=7818, online=1, error=(null))
16:41:10.638‖ Sync: <CBLRemoteSession: 0x60000009a5e0>: PUT /test-script/_local/8ec664a9942a235d12bbdafa8ccbdbdfe966ffc7
16:41:10.638| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: active, progress = 1 / 1, err: (null)
16:41:11.144‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] saved remote checkpoint '7818' (_rev=0-32)
16:41:11.144‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script] Progress: set active = 0
16:41:11.144‖ Sync: CBLRestPusher[http://syncgateway_url:4944/test-script]: postProgressChanged (1/1, active=0 (batch=0, net=0), lastSeq=7818, online=1, error=(null))
16:41:11.144| Sync: CBLReplication[to http://syncgateway_url:4944/test-script]: idle, progress = 1 / 1, err: (null)
16:41:42.212‖ ChangeTracker: CBLWebSocketChangeTracker[0x60c0001d7070 test-script]: Got a message:

[ajaykoppisetty]

Another weird thing just now observed is on dev environment it is using CBLSocketChangeTracker and on test it is using CBLWebSocketChangeTracker. Is there any configuration that we can to use only CBLSocketChangeTracker since it is working perfectly fine ?