Intermittent issue with saving checkpoint document

[afeick]

There is an intermittent problem with saving the last sequence (checkpoint document) after going offline and back online with non-continuous replication.

Library Version

1.4.1

.NET Runtime

.Net 4.6.2

Operating System / Device Details

Windows 10

Log Output

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://www.github.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://www.github.com:4984/zd01/_local/61dfc00635926c0b0f30e8962d2e9d7ea145d320

Expected behavior

After going offline and back online, the replicator should get any changes and update the checkpoint document with the latest sequence.

Actual behavior

The checkpoint document for the replicator is never updated, so it keeps processing the same set of changes every time it is started.

Looking at 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.

Steps To Reproduce

1. Run a replication on a timer
2. Go offline and wait for a period of time
3. Go back online
4. Sometimes the checkpoint document will be correctly updated with the new lastSequence, and sometimes it will not be updated.
5. When it is not updated, the replicator keeps processing the same changes every time it's started.

Reproduction Project

No sample project, but I've attached the CBLite.log and a Fiddler session

Sequence Issue.zip

[borrrden]

Your analysis is correct, and the fix seems straightforward enough. This will surely be in the next release. In the meantime, a workaround could be to not reuse the same replicator object.

[abhishekchouksey]

@borrrden Does this issue exist in CBL 2.0 in android? We are also seeing excessive document processing.

Here is log -- respective channel, there is nothing being changed at couchbase server; however, excessive document processing.

OneTimeReplicationJob  D  starting replication
                         V  channels: [dl-157145]
            LiteCoreJNI  I  [NATIVE] C4Replicator.create()
                         I  [NATIVE] C4Replicator.create() repl -> 0x0xa2f39980
                         I  [NATIVE] C4Replicator.getStatus() repl -> 0xa2f39980
                         I  [NATIVE] C4Replicator.getResponseHeaders() repl -> 0xa2f39980
                         I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
                         I  [NATIVE] C4Replicator.getResponseHeaders() repl -> 0xa2f39980
eplicationJob$subscribe  V  completed: 0 total: 0
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 0 | total: 0
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 0 total: 0
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 0 total: 200
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 0 | total: 200
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 0 total: 200
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 100 total: 200
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 100 | total: 200
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 100 total: 200 starts low, then jumps
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 33007 total: 2929270
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 33007 | total: 2929270
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 33007 total: 2929270
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 213120 total: 2929270
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 213120 | total: 2929270
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 213120 total: 2929270
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 409601 total: 2929270
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 409601 | total: 2929270
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 409601 total: 2929270
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 638837 total: 2929270
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 638837 | total: 2929270
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 638837 total: 2929270
            LiteCoreJNI  I  [NATIVE] C4Replicator.statusChangedCallback() repl -> 0x0xa2f39980 status -> 4
eplicationJob$subscribe  V  completed: 900821 total: 2929270
$inlined$forEach$lambda  V  task: 157145 channels: [dl-157145]: completed: 900821 | total: 2929270
           HomeActivity  D  updating progress for channels: [dl-157145]
                         V  completed: 900821 total: 2929270

[borrrden]

The 2.0 codebase is completely different than 1.x so it is not possible for the same issue to exist (though it is possible there is a similar one. Preseeded DB restarting replication from zero is an issue that will be fixed in 2.1). It would need separate analysis, and its own tracking issue (with more info) on its repo.