GoXDCR: Keys stuck in xmem queue (get replicated after mins), no errors reported

Build

4.0.0-2020

Testcase
--------
./testrunner -i INI_FILE.ini get-cbcollect-info=True,get-logs=True,stop-on-failure=False,replication_type=xmem,items=500000,item_count_timeout=600 -t xdcr.uniXDCR.unidirectional.load_with_ops,items=50000,value_size=128,ctopology=chain,rdirection=unidirection

Not consistently seen.

test log: https://friendpaste.com/5PRPCsFPfukJwFL0y3MFID

On .179, pls note it takes 10 mins to replicate a certain 13 keys stuck in xmem queue. The rest of the docs get replicated in no time.

StatisticsManager 2015-05-04T16:22:29.060-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:22:39.049-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:22:49.055-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:22:59.044-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:23:09.044-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:23:19.043-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:23:29.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:23:39.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:23:49.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:23:59.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:24:09.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:24:19.044-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:24:29.061-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:24:39.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:24:49.037-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:24:59.041-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:25:09.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:25:19.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:25:29.035-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:25:39.040-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:25:49.046-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:25:59.037-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:26:09.039-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:26:19.040-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:26:29.045-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:26:39.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:26:49.046-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:26:59.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:27:09.048-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:27:19.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:27:29.039-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:27:39.045-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:27:49.041-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:27:59.044-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:28:09.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:28:19.039-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:28:29.043-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:28:39.045-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:28:49.041-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:28:59.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:29:09.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:29:19.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:29:29.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:29:39.043-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:29:49.044-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:29:59.046-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:30:09.047-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:30:19.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:30:29.038-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:30:39.049-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:30:49.039-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:30:59.041-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:31:09.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:31:19.038-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:31:29.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:31:39.046-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:31:49.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:31:59.046-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:32:09.049-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:32:19.042-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13
StatisticsManager 2015-05-04T16:32:37.299-07:00 [INFO] total_doc=250000, docs_processed=249987, changes_left=13

StatisticsManager 2015-05-04T16:24:09.049-07:00 [INFO] Xmem xmem_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.181:11210_1 state =2 connType=MemConn received 124999 items, sent 124989 items, 0 items waiting to confirm, 10 in queue, getMeta's backoff_factor is 0, setMeta's backoff_factor is 0
StatisticsManager 2015-05-04T16:24:09.049-07:00 [INFO] Xmem xmem_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.181:11210_0 state =2 connType=MemConn received 125001 items, sent 124998 items, 0 items waiting to confirm, 3 in queue, getMeta's backoff_factor is 0, setMeta's backoff_factor is 0
StatisticsManager 2015-05-04T16:24:09.049-07:00 [INFO] Rounter Router_dcp_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.179:11210_0 = map[xmem_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.181:11210_0:125001]
StatisticsManager 2015-05-04T16:24:09.049-07:00 [INFO] Dcp dcp_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.179:11210_0 streamed 125001 items. [] streams inactive
StatisticsManager 2015-05-04T16:24:09.049-07:00 [INFO] Rounter Router_dcp_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.179:11210_1 = map[xmem_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.181:11210_1:124999]
StatisticsManager 2015-05-04T16:24:09.049-07:00 [INFO] Dcp dcp_298a47eadd1c71eb41f604d44bd12f99/default/default_172.23.105.179:11210_1 streamed 124999 items. [] streams inactive
ToplogyChangeDetector 2015-05-04T16:24:09.111-07:00 [INFO] validateSourceTopology...
PipelineManager 2015-05-04T16:24:12.172-07:00 [INFO] Replication Status = map[298a47eadd1c71eb41f604d44bd12f99/default/default:name=

, status=

, errors=

, progress=

1. No errors are reported
2. Why is pipeline not getting constructed after some timeout?