GoXDCR: 1 key missing in simple unixdcr with pause/resume

Build

---

4.0.0-1869

was not seen on 4.0.0-1817

Testcase
--------
./testrunner -i INI_FILE.ini -t xdcr.pauseResumeXDCR.PauseResumeTest.replication_with_pause_and_resume,items=50000,rdirection=unidirection,ctopology=chain,standard_buckets=1,sasl_buckets=1,pause=C1

test#8 in http://qa.sc.couchbase.com/view/BY%20COMPONENT/job/cen006-p0-xxdcr-vset09-00-goxdcr-pause-resume/64/consoleFull

Steps
------
1. C1[.3,.4] --> C2[.20,.67] on default, sasl and standard buckets
2. Load 50K keys to C1 on all 3 buckets
3. pause all replications during load
4. Resume immediately
5. verify keys on both clusters.

C2 has only 49999 keys on bucket default. 1 key 'C1-key-49500' missing.

[2015-04-17 14:22:28,717] - [xdcrnewbasetests:2007] INFO - Saw: vb_active_curr_items 50000 == 50000 expected on C1, default bucket
[2015-04-17 14:22:28,831] - [xdcrnewbasetests:2007] INFO - Saw: vb_active_curr_items 50000 == 50000 expected on C1, sasl_bucket_1 bucket
[2015-04-17 14:22:28,986] - [xdcrnewbasetests:2007] INFO - Saw: vb_active_curr_items 50000 == 50000 expected on C1, standard_bucket_1 bucket
[2015-04-17 14:22:29,328] - [xdcrnewbasetests:2041] INFO - Saw: vb_replica_curr_items 50000 == 50000 expected on C1, default bucket
[2015-04-17 14:22:29,430] - [xdcrnewbasetests:2041] INFO - Saw: vb_replica_curr_items 50000 == 50000 expected on C1, sasl_bucket_1 bucket
[2015-04-17 14:22:29,532] - [xdcrnewbasetests:2041] INFO - Saw: vb_replica_curr_items 50000 == 50000 expected on C1, standard_bucket_1 bucket
[2015-04-17 14:22:31,345] - [xdcrnewbasetests:1996] WARNING - Not Ready: vb_active_curr_items 24999 == 50000 expected on C2, default bucket
:
:
:

[2015-04-17 14:28:38,381] - [xdcrnewbasetests:2029] WARNING - Not Ready: vb_replica_curr_items 49999 == 50000 expected on C2, default bucket

Jenkins link to logs attached.

On .3 I see changes_left=1, no errors in errors[]. I think we discussed this earlier, if there are no keys in dcp queue and changes_left doesn't go to 0 in 'x' secs, we should probably report an error.

StatisticsManager 2015-04-17T14:21:23.475-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:22:23.387-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:23:23.395-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:24:23.384-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:25:23.394-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:26:23.382-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:27:23.399-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:28:23.388-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:29:23.393-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:30:23.393-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:31:23.393-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:32:23.390-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1

StatisticsManager 2015-04-17T14:32:23.390-07:00 [INFO] total_doc=25000, docs_processed=24999, changes_left=1
StatisticsManager 2015-04-17T14:32:23.391-07:00 [INFO] Stats for pipeline 500adea894f1b1c449b7ba646e25dac3/default/default-701108735 {"CkptMgr": {"num_checkpoints": 10, "num_failedckpts": 0, "time_committing": {"count": 10, "max": 210000, "mean": 104400, "min": 77000}}, "Errors": "[

{\"time\":\"2015-04-17T14:18:42.568064562-07:00\",\"errMsg\":\"Failed to get starting seqno for pipeline 500adea894f1b1c449b7ba646e25dac3/default/default-758701730\"}

]", "Overview":

{"bandwidth_usage": 0, "changes_left": 1, "data_replicated": 14293873, "docs_checked": 24999, "docs_failed_cr_source": 0, "docs_filtered": 0, "docs_opt_repd": 0, "docs_processed": 24999, "docs_received_from_dcp": 25000, "docs_rep_queue": 0, "docs_written": 24999, "num_checkpoints": 10, "num_failedckpts": 0, "rate_doc_checks": 0, "rate_doc_opt_repd": 0, "rate_received_from_dcp": 0, "rate_replicated": 0, "size_rep_queue": 0, "time_committing": 104400, "wtavg_docs_latency": 0, "wtavg_meta_latency": 0}

, "Progress": "Pipeline is running", "Status": "Replicating", "XDCRRouter":

{"docs_filtered": 0}

, "dcp_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.3:11210_0":

{"docs_received_from_dcp": 12499}

, "dcp_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.3:11210_1":

{"docs_received_from_dcp": 12501}

, "xmem_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.20:11210_0":

{"data_replicated": 7146654, "docs_failed_cr_source": 0, "docs_opt_repd": 0, "docs_rep_queue": 0, "docs_written": 12499, "size_rep_queue": 0}

, "xmem_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.20:11210_1": {"data_replicated": 7147219, "docs_failed_cr_source": 0, "docs_opt_repd": 0, "docs_rep_queue": 0, "docs_written": 12500, "size_rep_queue": 0}}

dcp streamed 12499 and 12501 items in 2 source nozzles

StatisticsManager 2015-04-17T14:31:23.394-07:00 [INFO] Dcp dcp_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.3:11210_0 streamed 12499 items. [] streams inactive
StatisticsManager 2015-04-17T14:31:23.394-07:00 [INFO] Rounter Router_dcp_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.3:11210_1 = map[xmem_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.20:11210_1:12501]
StatisticsManager 2015-04-17T14:31:23.394-07:00 [INFO] Dcp dcp_500adea894f1b1c449b7ba646e25dac3/default/default_172.23.105.3:11210_1 streamed 12501 items. [] streams inactive
PipelineManager 2015-04-17T14:31:25.854-07:00 [INFO] Replication Status = map[500adea894f1b1c449b7ba646e25dac3/default/default:name=

{500adea894f1b1c449b7ba646e25dac3/default/default}

, status=

{Replicating}

, errors={[

{"time":"2015-04-17T14:18:42.568064562-07:00","errMsg":"Failed to get starting seqno for pipeline 500adea894f1b1c449b7ba646e25dac3/default/default-758701730"}

]}, progress=

{Pipeline is running}