Excessive re-processing of documents after going back online. What gives?

pkramer · June 18, 2018, 4:15pm

Using CBL .NET 1.4.1.2

After a short period of being offline, CBLite is re-downloading tons of old revisions that I am certain did not change during the period of downtime.

I can attach the full log, but it’s rather extensive. Here is a short snippet of what happens when we go back online and then start a one-shot (non-continuous) pull replication.

`
2018-06-18 09:31:55,874 DEBUG [3792 ] Starting one-shot pull replication on <database_name> for the following channels:

<channel1>
<channel2>

2018-06-18 09:31:55,874 DEBUG [3792 ] Waiting to acquire lock for replication Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff.
2018-06-18 09:31:55,874 DEBUG [3792 ] Lock acquired for replication Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff
2018-06-18 09:31:55,874 DEBUG [3792 ] Starting Couchbase Lite replication: Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff with filters sync_gateway/bychannel
2018-06-18 09:31:55,874 DEBUG [3792 ] [SYNC (Replication)] Start() called, firing Start…
2018-06-18 09:31:55,874 DEBUG [3792 ] [SYNC (Replication)] Preparing to fire Start
2018-06-18 09:31:55,874 DEBUG [3792 ] Waiting for replication Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff to finish…
2018-06-18 09:31:57,668 DEBUG [4536 ] [SYNC (Replication)] Preparing to fire GoOnline
2018-06-18 09:31:57,668 DEBUG [4536 ] [SYNC (Replication)] Preparing to fire GoOnline
2018-06-18 09:31:57,746 DEBUG [5612 ] [SYNC (Replication)] Offline => Running (ed8db2ce-1206-4296-a82d-2ea53e2043ff)
2018-06-18 09:31:57,746 INFO [5612 ] [SYNC (Replication)] Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff going online
2018-06-18 09:31:57,746 DEBUG [5612 ] [SYNC (Replication)] NotifyChangeListeners (259/259, state=Offline (batch=0, net=1))
2018-06-18 09:31:57,746 DEBUG [5844 ] HandleReplicationChanged: Waiting to acquire lock for Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff
2018-06-18 09:31:57,746 DEBUG [5844 ] HandleReplicationChanged: Lock acquired for Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff
2018-06-18 09:31:57,746 DEBUG [5844 ] Replication changed event received for Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff. Current Status: [Active], Previous Status: [Offline], Is Running: [True], Changes Count: [259], Completed Count: [259], Last Error: []
2018-06-18 09:31:57,746 DEBUG [5844 ] Replication Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff is now active for database ‘<database_name>’. Blocking threads until replication goes idle.
2018-06-18 09:31:57,746 DEBUG [5844 ] Replication Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff has processed all changes for database ‘<database_name>’. Raising CaughtUp event.
2018-06-18 09:31:57,746 DEBUG [5844 ] Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff status: Active
2018-06-18 09:31:57,761 DEBUG [1332 ] [SYNC (Replication)] Offline => Running (e471da3e-d0c5-4afd-be79-73b8f05e4977)
2018-06-18 09:31:57,761 INFO [1332 ] [SYNC (Replication)] Puller e471da3e-d0c5-4afd-be79-73b8f05e4977 going online
2018-06-18 09:31:57,761 DEBUG [1332 ] [SYNC (Replication)] NotifyChangeListeners (0/0, state=Offline (batch=0, net=1))
2018-06-18 09:31:57,761 DEBUG [5612 ] HandleReplicationChanged: Waiting to acquire lock for Puller e471da3e-d0c5-4afd-be79-73b8f05e4977
2018-06-18 09:31:57,761 DEBUG [5612 ] HandleReplicationChanged: Lock acquired for Puller e471da3e-d0c5-4afd-be79-73b8f05e4977
2018-06-18 09:31:57,761 DEBUG [5612 ] Replication changed event received for Puller e471da3e-d0c5-4afd-be79-73b8f05e4977. Current Status: [Active], Previous Status: [Offline], Is Running: [True], Changes Count: [0], Completed Count: [0], Last Error: []
2018-06-18 09:31:57,761 DEBUG [5612 ] Replication Puller e471da3e-d0c5-4afd-be79-73b8f05e4977 is now active for database ‘pcr_tenant_bff750cb-338c-e711-80c4-0050569c053d’. Blocking threads until replication goes idle.
2018-06-18 09:31:57,777 DEBUG [2520 ] Invoking push filter function for revision patientCareRecord_bff750cb-338c-e711-80c4-0050569c053d_2bdb22cd-98ca-4bab-a0fb-26129b8f8b80 (5-ee3809474c3122610e2c84949990ae9a)
2018-06-18 09:31:57,777 DEBUG [2520 ] Revision patientCareRecord_bff750cb-338c-e711-80c4-0050569c053d_2bdb22cd-98ca-4bab-a0fb-26129b8f8b80 (5-ee3809474c3122610e2c84949990ae9a) will be pushed because the filter function ‘pushFilter_Pusher 773168fa-a387-43ac-9b46-f810b361108c’ returned True.
2018-06-18 09:31:57,777 DEBUG [2520 ] Pending document IDs for Pusher 773168fa-a387-43ac-9b46-f810b361108c: patientCareRecord_bff750cb-338c-e711-80c4-0050569c053d_2bdb22cd-98ca-4bab-a0fb-26129b8f8b80
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/260, state=Running (batch=0, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/261, state=Running (batch=1, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/262, state=Running (batch=2, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/263, state=Running (batch=3, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/264, state=Running (batch=4, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/265, state=Running (batch=5, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/266, state=Running (batch=6, net=1))
2018-06-18 09:31:58,276 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/267, state=Running (batch=7, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/268, state=Running (batch=8, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/269, state=Running (batch=9, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/270, state=Running (batch=10, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/271, state=Running (batch=11, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/272, state=Running (batch=12, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/273, state=Running (batch=13, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/274, state=Running (batch=14, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/275, state=Running (batch=15, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/276, state=Running (batch=16, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/277, state=Running (batch=17, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/278, state=Running (batch=18, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/279, state=Running (batch=19, net=1))
2018-06-18 09:31:58,292 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/280, state=Running (batch=20, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/281, state=Running (batch=21, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/282, state=Running (batch=22, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/283, state=Running (batch=23, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/284, state=Running (batch=24, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/285, state=Running (batch=25, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/286, state=Running (batch=26, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/287, state=Running (batch=27, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/288, state=Running (batch=28, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/289, state=Running (batch=29, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/290, state=Running (batch=30, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/291, state=Running (batch=31, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/292, state=Running (batch=32, net=1))
2018-06-18 09:31:58,307 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/293, state=Running (batch=33, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/294, state=Running (batch=34, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/295, state=Running (batch=35, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/296, state=Running (batch=36, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/297, state=Running (batch=37, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/298, state=Running (batch=38, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/299, state=Running (batch=39, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/300, state=Running (batch=40, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/301, state=Running (batch=41, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/302, state=Running (batch=42, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/303, state=Running (batch=43, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/304, state=Running (batch=44, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/305, state=Running (batch=45, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/306, state=Running (batch=46, net=1))
2018-06-18 09:31:58,323 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/307, state=Running (batch=47, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/308, state=Running (batch=48, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/309, state=Running (batch=49, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/310, state=Running (batch=50, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/311, state=Running (batch=51, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/312, state=Running (batch=52, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/313, state=Running (batch=53, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/314, state=Running (batch=54, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/315, state=Running (batch=55, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/316, state=Running (batch=56, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/317, state=Running (batch=57, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/318, state=Running (batch=58, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/319, state=Running (batch=59, net=1))
2018-06-18 09:31:58,338 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/320, state=Running (batch=60, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/321, state=Running (batch=61, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/322, state=Running (batch=62, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/323, state=Running (batch=63, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/324, state=Running (batch=64, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/325, state=Running (batch=65, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/326, state=Running (batch=66, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/327, state=Running (batch=67, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/328, state=Running (batch=68, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/329, state=Running (batch=69, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/330, state=Running (batch=70, net=1))
2018-06-18 09:31:58,354 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/331, state=Running (batch=71, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/332, state=Running (batch=72, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/333, state=Running (batch=73, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/334, state=Running (batch=74, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/335, state=Running (batch=75, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/336, state=Running (batch=76, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/337, state=Running (batch=77, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/338, state=Running (batch=78, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/339, state=Running (batch=79, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/340, state=Running (batch=80, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/341, state=Running (batch=81, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/342, state=Running (batch=82, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/343, state=Running (batch=83, net=1))
2018-06-18 09:31:58,370 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/344, state=Running (batch=84, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/345, state=Running (batch=85, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/346, state=Running (batch=86, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/347, state=Running (batch=87, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/348, state=Running (batch=88, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/349, state=Running (batch=89, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/350, state=Running (batch=90, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/351, state=Running (batch=91, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/352, state=Running (batch=92, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/353, state=Running (batch=93, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/354, state=Running (batch=94, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/355, state=Running (batch=95, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/356, state=Running (batch=96, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/357, state=Running (batch=97, net=1))
2018-06-18 09:31:58,385 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/358, state=Running (batch=98, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/359, state=Running (batch=99, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/360, state=Running (batch=100, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/361, state=Running (batch=101, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/362, state=Running (batch=102, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/363, state=Running (batch=103, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/364, state=Running (batch=104, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/365, state=Running (batch=105, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/367, state=Running (batch=106, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/368, state=Running (batch=108, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/369, state=Running (batch=109, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/370, state=Running (batch=110, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/371, state=Running (batch=111, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/372, state=Running (batch=112, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/373, state=Running (batch=113, net=1))
2018-06-18 09:31:58,401 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/374, state=Running (batch=114, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/375, state=Running (batch=115, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/376, state=Running (batch=116, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/377, state=Running (batch=117, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/378, state=Running (batch=118, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/379, state=Running (batch=119, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/380, state=Running (batch=120, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/381, state=Running (batch=121, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/382, state=Running (batch=122, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/383, state=Running (batch=123, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/384, state=Running (batch=124, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/387, state=Running (batch=125, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/388, state=Running (batch=128, net=1))
2018-06-18 09:31:58,416 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/389, state=Running (batch=129, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/390, state=Running (batch=130, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/391, state=Running (batch=131, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/392, state=Running (batch=132, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/393, state=Running (batch=133, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/396, state=Running (batch=134, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/397, state=Running (batch=137, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/400, state=Running (batch=138, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/401, state=Running (batch=141, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/405, state=Running (batch=142, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/406, state=Running (batch=146, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/407, state=Running (batch=147, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/408, state=Running (batch=148, net=1))
2018-06-18 09:31:58,432 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/409, state=Running (batch=149, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/410, state=Running (batch=150, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/411, state=Running (batch=151, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/412, state=Running (batch=152, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/413, state=Running (batch=153, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/414, state=Running (batch=154, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/415, state=Running (batch=155, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/416, state=Running (batch=156, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/417, state=Running (batch=157, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/418, state=Running (batch=158, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/419, state=Running (batch=159, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/424, state=Running (batch=160, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/425, state=Running (batch=165, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/426, state=Running (batch=166, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/432, state=Running (batch=167, net=1))
2018-06-18 09:31:58,448 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/441, state=Running (batch=173, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/442, state=Running (batch=182, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/443, state=Running (batch=183, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/444, state=Running (batch=184, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/447, state=Running (batch=185, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/454, state=Running (batch=188, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/456, state=Running (batch=195, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/460, state=Running (batch=197, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/461, state=Running (batch=201, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/462, state=Running (batch=202, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/466, state=Running (batch=203, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] [SYNC (Replication)] NotifyChangeListeners (259/467, state=Running (batch=207, net=1))
2018-06-18 09:31:58,463 DEBUG [4168 ] HandleReplicationChanged: Waiting to acquire lock for Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff
2018-06-18 09:31:58,463 DEBUG [4168 ] HandleReplicationChanged: Lock acquired for Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff
2018-06-18 09:31:58,463 DEBUG [4168 ] Replication changed event received for Puller ed8db2ce-1206-4296-a82d-2ea53e2043ff. Current Status: [Active], Previous Status: [Active], Is Running: [True], Changes Count: [260], Completed Count: [259], Last Error: []
`

The replicator continues to raise “Changed” events, and the Count keeps incrementing up to about 470 changes I have noticed. Revisions are definitely being re-downloaded and raised as changes by the database because then we get a bunch of “Changed” notifications from the database for old documents that were previously on the device but are no longer.

Really at a loss for how I might address this myself. It seems like a bug, and it also results in our most recent changes not being reflected for quite some time (in one case 4 minutes).

Any help is much appreciated. @borrrden

borrrden · June 19, 2018, 4:41am

If the checkpoint fails to sync it may result in this situation since any disagreement between client and server mandates checking every revision since the beginning of time (fundamental part of the algorithm). However, if it makes a difference, this doesn’t mean it is downloading every revision again, it is just asking for a list, and going through checking which ones it has. This will be reflected in the logs (check for logs containing the word “checkpoint”). If you have purged documents, this will result in them being downloaded again though as purging is a destructive operation that leaves no trace. Does this sound like what is happening? If you are having issues with too much data being transferred then it might be worth investigating creating subsets of the data with the sync function on the server side.

pkramer · June 19, 2018, 4:50am

We are actually purging documents when we get _removed and tombstones. We had to do this to workaround a different issue where if a channel change removed a document from the device, it would never be synced again if channel access was given back at a later point in time. I’d have to pull the CB support ticket number for the exact scenario details, it has been a while. I think it also had something to do with documents that had attachments, so it is possible it has been fixed in 1.4.1.2 of CBL or Sync Gateway 1.5.

I believe my colleague just encountered this in the logs earlier today after looking at the source code and watching Fiddler activity.

It sounds like not purging the documents might address the “replay” we are seeing here…?

borrrden · June 19, 2018, 4:58am

What I can say for sure right now is that if you purged a document, and then you had a replication that went over that document again (for any reason, such as the document being updated, the replicator restarting, etc) then that document would be downloaded again. Also, if the checkpoint sync fails (it’s supposed to be hard for it to fail in this specific way, but not impossible) and the server and client get a differing last sequence value then the replication will literally start from 0 instead of the last sequence, meaning the change tracker will send all changes from the beginning of time and the client will go through and request the ones that it does not have while simply skipping the rest.

I am not entirely sure which support case you are referring to but unless it was specifically targeted for a four digit release then a fix will not be present (unless by accident) in .NET. Four digit releases for Couchbase Lite .NET are only for two reasons:

A fix for a specific support case (or in uncommon situations, a group of support cases)
A fake Nuget version for use after I goofed my only shot at the three digit version (The library version will still be three digits in this case though)

afeick · June 19, 2018, 4:27pm

The cause of this appears to be an intermittent problem with saving the last sequence (checkpoint document) after going offline and back online. Here’s a bit of the CBLite log that indicates what’s going on here:

2018-06-18 17:09:27,587 INFO  [TabletPCR.exe] [9144] [SYNC (Replication)] Puller aea6bc7c-aae5-4eb2-ba04-207e73fe8e07 checkpointing sequence=
2018-06-18 17:09:27,634 DEBUG [TabletPCR.exe] [9144] [SYNC (RemoteSession)] aea6bc7c-aae5-4eb2-ba04-207e73fe8e07 - Sending PUT request to: https://intsync.zollonline.com:4984/zd01/_local/61dfc00635926c0b0f30e8962d2e9d7ea145d320
2018-06-18 17:09:27,649 INFO  [TabletPCR.exe] [9144] [SYNC (RemoteSession)] Client is disposed, aborting request to https://intsync.zollonline.com:4984/zd01/_local/61dfc00635926c0b0f30e8962d2e9d7ea145d320

In the source for Replication.SaveLastSequence it relies on the completion block passed into RemoteSesssion.SendAsyncRequest to set _savingCheckpoint = false at Replication.cs line 1633.

Unfortunately, the error logged from SendAsyncRequest returns null without calling the completionHandler. This means the _savingCheckpoint variable is never set to false, and it will never save another checkpoint for the life of the replicator because of the check at Replication.cs line 1605 to delay saving the checkpoint if _savingCheckpoint is true.

Since the checkpoint is never updated, the replicator keeps getting the changes since whatever lastSequence had been in the checkpoint document from before.

I have the rest of the logs and the Fiddler session saved if you need more information.

afeick · June 22, 2018, 2:30pm

An issue has been added for this: https://github.com/couchbase/couchbase-lite-net/issues/1036