GoXDCR: Pipeline gets reconstructed frequently after rebalance-in, delaying replication

Build

---

4.0.0-1817

Testcase
--------
./testrunner -i INI_FILE.ini -t xdcr.pauseResumeXDCR.PauseResumeTest.replication_with_pause_and_resume,items=30000,rdirection=bidirection,rebalance_in=C1-C2,pause_wait=10,pause=C1-C2

Steps

---

1. C1 [.3,.4] <--> C2 [.20,.67], default bucket, default params
2. Pause replication, rebalance in .102 to C1 and .53 to C2.
3. Resume replication, verify keys on C1 and C2.

[2015-04-14 12:53:02,640] - [task:456] INFO - rebalancing was completed with progress: 100% in 40.1552360058 sec
[2015-04-14 12:53:03,936] - [task:456] INFO - rebalancing was completed with progress: 100% in 40.2507431507 sec

[2015-04-14 12:54:13,939] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:19,010] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:24,075] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:29,148] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:34,218] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:39,295] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:44,458] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:49,539] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 53792 == 60000 expected on C1, default bucket
[2015-04-14 12:54:54,623] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 54589 == 60000 expected on C1, default bucket
[2015-04-14 12:54:59,691] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 55576 == 60000 expected on C1, default bucket
[2015-04-14 12:55:04,757] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 56273 == 60000 expected on C1, default bucket
[2015-04-14 12:55:09,851] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57344 == 60000 expected on C1, default bucket
[2015-04-14 12:55:14,947] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:20,023] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:25,108] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:30,181] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:35,269] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:40,352] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:45,423] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:50,515] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:55:55,598] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:00,676] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:05,766] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:10,841] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:15,921] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:21,010] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:26,084] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:31,160] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:36,248] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:41,310] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:46,396] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 57978 == 60000 expected on C1, default bucket
[2015-04-14 12:56:51,478] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:56:56,558] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:01,643] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:06,704] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:11,800] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_active_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:16,807] - [xdcrnewbasetests] [140695021664000] - ERROR - ERROR: Timed-out waiting for active item count to match
[2015-04-14 12:57:16,954] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:20,071] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:23,139] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:26,206] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:29,307] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:32,403] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:35,505] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:38,579] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:41,651] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:44,714] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:47,795] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:50,879] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:53,972] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:57:57,046] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:00,132] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:03,194] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:06,252] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:09,324] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:12,391] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:15,463] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:18,528] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:21,597] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58151 == 60000 expected on C1, default bucket
[2015-04-14 12:58:24,693] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58361 == 60000 expected on C1, default bucket
[2015-04-14 12:58:27,754] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:30,846] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:33,911] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:36,982] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:40,047] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:43,113] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:46,184] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:49,278] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:52,340] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:55,403] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:58:58,497] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:01,577] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:04,665] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:07,748] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:10,845] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:13,937] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:17,005] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:20,094] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:23,158] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:26,232] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:29,314] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:32,417] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:35,494] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:38,560] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:41,643] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:44,715] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:47,938] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:51,004] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:54,064] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 12:59:57,131] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58381 == 60000 expected on C1, default bucket
[2015-04-14 13:00:00,195] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58512 == 60000 expected on C1, default bucket
[2015-04-14 13:00:03,270] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58512 == 60000 expected on C1, default bucket
[2015-04-14 13:00:06,349] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58512 == 60000 expected on C1, default bucket
[2015-04-14 13:00:09,424] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58512 == 60000 expected on C1, default bucket
[2015-04-14 13:00:12,482] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58512 == 60000 expected on C1, default bucket
[2015-04-14 13:00:15,553] - [xdcrnewbasetests] [140695021664000] - WARNING - Not Ready: vb_replica_curr_items 58512 == 60000 expected on C1, default bucket

On .20's goxdcr.log, I see pipeline stuck and recreated 4 times in a duration of 7 mins leading to the above delay in replication. The test timed out after 6 mins.

PipelineManager 2015-04-14T13:05:47.200-07:00 [INFO] Replication Status = map[ed6893551f68913db939ca9944c58e18/default/default:name=

{ed6893551f68913db939ca9944c58e18/default/default}

, status=

{Replicating}

, errors={[

{"time":"2015-04-14T12:59:08.862543791-07:00","errMsg":"map[xmem_ed6893551f68913db939ca9944c58e18/default/default_172.23.105.102:11210_0:Failed to resend document C2-key-26238, has tried to resend it 11, maximum retry 10 reached]"}

,

{"time":"2015-04-14T12:56:21.076381139-07:00","errMsg":"map[xmem_ed6893551f68913db939ca9944c58e18/default/default_172.23.105.3:11210_1:Xmem is stuck]"}

,

{"time":"2015-04-14T12:54:08.583775308-07:00","errMsg":"map[xmem_ed6893551f68913db939ca9944c58e18/default/default_172.23.105.3:11210_1:Xmem is stuck]"}

,

{"time":"2015-04-14T12:52:29.527270683-07:00","errMsg":"Failed to get starting seqno for pipeline ed6893551f68913db939ca9944c58e18/default/default-547973460"}

]}, progress=

{Pipeline is running}

I see many failures like the above.