GoXDCR: "Unexpected server error" while trying to delete replication (metakv recursive delete fails with err=Rev mismatch)

Build

---

4.0.0-1650

Testcase
--------
./testrunner -i -p demand_encryption=1 -t xdcr.biXDCR.bidirectional.replication_while_rebooting_a_non_master_src_dest_node,items=10000,rdirection=bidirection,sasl_buckets=1,ctopology=chain

test#13 in http://qa.sc.couchbase.com/view/BY%20COMPONENT/job/cen006-p0-xxdcr-vset00-02-goxdcr-bixdcr-ssl/15/consoleFull

Steps
1. C1 [.45,.46] <--> C2 [.47,.48], default and sasl_bucket_1
2. Load 10K keys on C1 and C2
3. reboot .46
4. verify keys

[2015-03-25 18:17:24,424] - [xdcrnewbasetests] [139771590473472] - INFO - ==== XDCRNewbasetests cleanup is started for test #13 replication_while_rebooting_a_non_master_src_dest_node ====
[2015-03-25 18:17:24,424] - [xdcrnewbasetests] [139771590473472] - INFO - removing xdcr/nodes settings
[2015-03-25 18:17:31,953] - [rest_client] [139771590473472] - INFO - Deleting replication /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0%2Fdefault%2Fdefault
[2015-03-25 18:18:02,162] - [rest_client] [139771590473472] - ERROR - http://172.23.106.45:8091//controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0%2Fdefault%2Fdefault error 500 reason: unknown ["Unexpected server error, request logged."]
[2015-03-25 18:18:02,162] - [rest_client] [139771590473472] - INFO - Deleting replication /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0%2Fsasl_bucket_1%2Fsasl_bucket_1
[2015-03-25 18:18:32,359] - [rest_client] [139771590473472] - ERROR - http://172.23.106.45:8091//controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0%2Fsasl_bucket_1%2Fsasl_bucket_1 error 500 reason: unknown ["Unexpected server error, request logged."]
[2015-03-25 18:18:40,910] - [rest_client] [139771590473472] - INFO - removing remote cluster name:remote_cluster_C1-C2
[2015-03-25 18:19:01,592] - [rest_client] [139771590473472] - ERROR - socket error while connecting to http://172.23.106.45:8091/pools/default/remoteClusters/remote_cluster_C1-C2? error [Errno 111] Connection refused

In goxdcr.log on .45, I see replication getting deleted @ 18:18:03 but metakv fails to delete checkpoints

GenericSupervisor2015/03/25 18:17:31.368999 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
HttpServer2015/03/25 18:17:31.467194 [INFO] Request received from ServeHTTP. r=&

{DELETE /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0/default/default HTTP/1.1 1 1 map[Content-Type:[application/x-www-form-urlencoded] Menelaus_auth-Role:[admin] User-Agent:[Python-httplib2/$Rev: 259 $] Accept-Encoding:[identity] Authorization:[Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==] Menelaus_auth-Token:[undefined] Menelaus_auth-User:[Administrator] Content-Length:[0] Accept:[*/*]] 0xbc7300 0 [] false 172.23.106.45:8091 map[] map[] <nil> map[] 127.0.0.1:35330 /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0/default/default <nil>}

with path, /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0/default/default and method, DELETE
AdminPort2015/03/25 18:17:31.467263 [INFO] Request key decoded: controller/cancelXDCR/dynamic/DELETE
AdminPort2015/03/25 18:17:31.467291 [INFO] Start authAdminCreds
AdminPort2015/03/25 18:17:31.467329 [INFO] creds user = Administrator
AdminPort2015/03/25 18:17:31.467337 [INFO] done with authentication
AdminPort2015/03/25 18:17:31.467363 [INFO] doDeleteReplicationRequest
ReplicationManager2015/03/25 18:17:31.467393 [INFO] Deleting replication bb3498305c12d847e54445ec71d21ff0/default/default
HttpServer2015/03/25 18:17:32.218481 [INFO] Request received from ServeHTTP. r=&

{GET /stats/buckets/default HTTP/1.1 1 1 map[Authorization:[Basic QDowNzc5MDI5OGI1OGM1OWI4NzRhZWFkYWY1ZjdjMzMyMw==] Accept:[application/json]] 0xbc7300 0 [] false 127.0.0.1:9998 map[] map[] <nil> map[] 127.0.0.1:48135 /stats/buckets/default <nil>}

with path, /stats/buckets/default and method, GET
HttpServer2015/03/25 18:17:32.218590 [INFO] Request received from ServeHTTP. r=&

{GET /stats/buckets/sasl_bucket_1 HTTP/1.1 1 1 map[Authorization:[Basic QDowNzc5MDI5OGI1OGM1OWI4NzRhZWFkYWY1ZjdjMzMyMw==] Accept:[application/json]] 0xbc7300 0 [] false 127.0.0.1:9998 map[] map[] <nil> map[] 127.0.0.1:34832 /stats/buckets/sasl_bucket_1 <nil>}

with path, /stats/buckets/sasl_bucket_1 and method, GET
HttpServer2015/03/25 18:17:33.976175 [INFO] Request received from ServeHTTP. r=&

{GET /pools/default/remoteClusters HTTP/1.1 1 1 map[Authorization:[Basic QDowNzc5MDI5OGI1OGM1OWI4NzRhZWFkYWY1ZjdjMzMyMw==] Accept:[application/json]] 0xbc7300 0 [] false 127.0.0.1:9998 map[] map[] <nil> map[] 127.0.0.1:46299 /pools/default/remoteClusters <nil>}

with path, /pools/default/remoteClusters and method, GET
Utils2015/03/25 18:17:34.243699 [INFO] client={http://Administrator:password@172.23.106.47:8091

{Administrator password} {map[sasl:2.3.4 stdlib:1.19.4 os_mon:2.2.14 ale:4.0.0-1650-rel-enterprise ns_server:4.0.0-1650-rel-enterprise crypto:3.2 inets:5.9.8 ssl:5.3.3 lhttpc:1.3.0 public_key:0.21 asn1:2.0.4 kernel:2.16.4] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
HttpServer2015/03/25 18:17:34.244187 [INFO] Request received from ServeHTTP. r=&{GET /pools/default/replicationInfos HTTP/1.1 1 1 map[Authorization:[Basic QDowNzc5MDI5OGI1OGM1OWI4NzRhZWFkYWY1ZjdjMzMyMw==] Accept:[application/json]] 0xbc7300 0 [] false 127.0.0.1:9998 map[] map[] <nil> map[] 127.0.0.1:53058 /pools/default/replicationInfos <nil>}
with path, /pools/default/replicationInfos and method, GET
GenericSupervisor2015/03/25 18:17:36.377849 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:17:36.377880 [INFO] Child AdminportSupervisor of supervisor ReplicationManagerSupervisor missed 1 consecutive heart beats
GenericSupervisor2015/03/25 18:17:36.378964 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
GenericSupervisor2015/03/25 18:17:40.379265 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:17:40.379347 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
RemoteClusterService2015/03/25 18:17:41.130907 [INFO] Refresh remote cluster reference remoteCluster/bb3498305c12d847e54445ec71d21ff0
RemoteClusterService2015/03/25 18:17:41.130934 [INFO] Remote Cluster reference 172.23.106.47:8091 need to be updated
Utils2015/03/25 18:17:42.571243 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password}

{map[lhttpc:1.3.0 os_mon:2.2.14 public_key:0.21 kernel:2.16.4 ale:4.0.0-1650-rel-enterprise inets:5.9.8 ssl:5.3.3 asn1:2.0.4 ns_server:4.0.0-1650-rel-enterprise crypto:3.2 sasl:2.3.4 stdlib:1.19.4] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [

{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
Utils2015/03/25 18:17:43.322008 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password} {map[os_mon:2.2.14 asn1:2.0.4 ale:4.0.0-1650-rel-enterprise inets:5.9.8 crypto:3.2 stdlib:1.19.4 lhttpc:1.3.0 kernel:2.16.4 ns_server:4.0.0-1650-rel-enterprise ssl:5.3.3 sasl:2.3.4 public_key:0.21] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}

]}}
GenericSupervisor2015/03/25 18:17:44.379704 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:17:44.379783 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
RemoteClusterService2015/03/25 18:17:44.594370 [INFO] Pool.Nodes=[

{262144 active http://172.23.106.47:8092/ 172.23.106.47:8091 map[ops:0 vb_replica_curr_items:20000 curr_items_tot:40000 ep_bg_fetched:0 cmd_get:0 couch_docs_actual_disk_size:1.0995255e+08 couch_docs_data_size:9.9510272e+07 couch_views_actual_disk_size:0 couch_views_data_size:0 curr_items:20000 get_hits:0 mem_used:1.12125744e+08] 3104 3104 1.649303552e+09 4.069695488e+09 x86_64-unknown-linux-gnu map[direct:11210 sslProxy:11214 httpsMgmt:18091 httpsCAPI:18092 proxy:11211] healthy 10275 4.0.0-1650-rel-enterprise true}

{262144 active http://172.23.106.48:8092/ 172.23.106.48:8091 map[couch_docs_actual_disk_size:1.0659004e+08 couch_docs_data_size:0 mem_used:1.06476984e+08 vb_replica_curr_items:20000 ops:0 cmd_get:0 couch_views_actual_disk_size:0 couch_views_data_size:0 curr_items:20000 curr_items_tot:40000 ep_bg_fetched:0 get_hits:0] 3104 3104 2.247155712e+09 4.069695488e+09 x86_64-unknown-linux-gnu map[sslProxy:11214 httpsMgmt:18091 httpsCAPI:18092 proxy:11211 direct:11210] healthy 1240 4.0.0-1650-rel-enterprise false}

]
RemoteClusterService2015/03/25 18:17:44.594432 [INFO] Remote cluster reference remoteCluster/bb3498305c12d847e54445ec71d21ff0 is cached, cache =&

{remoteCluster/bb3498305c12d847e54445ec71d21ff0 [172.23.106.48:8091] 0xc209f8c990}

Utils2015/03/25 18:17:44.645475 [INFO] client={http://Administrator:password@172.23.106.47:8091

{Administrator password} {map[public_key:0.21 inets:5.9.8 sasl:2.3.4 stdlib:1.19.4 lhttpc:1.3.0 os_mon:2.2.14 asn1:2.0.4 kernel:2.16.4 ale:4.0.0-1650-rel-enterprise ns_server:4.0.0-1650-rel-enterprise crypto:3.2 ssl:5.3.3] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
PipelineManager2015/03/25 18:17:45.007030 [INFO] Replication Status = map[bb3498305c12d847e54445ec71d21ff0/default/default:name={bb3498305c12d847e54445ec71d21ff0/default/default}, status={Replicating}, errors={[]}, progress={Pipeline is running}
bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1:name={bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1}, status={Replicating}, errors={[]}, progress={Pipeline is running}
]
ClusterInfoService2015/03/25 18:17:46.060080 [INFO] version=[3 0], effectiveVersion=12288
ToplogyChangeDetector2015/03/25 18:17:46.060481 [INFO] Detected that remote cluster 172.23.106.47:8091 has upgraded to 3.0 or above
ToplogyChangeDetector2015/03/25 18:17:46.060670 [INFO] validateSourceTopology...
RemoteClusterService2015/03/25 18:17:46.907918 [INFO] Refresh remote cluster reference remoteCluster/bb3498305c12d847e54445ec71d21ff0
RemoteClusterService2015/03/25 18:17:46.907944 [INFO] Remote Cluster reference 172.23.106.47:8091 need to be updated
Utils2015/03/25 18:17:46.962982 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password}

{map[lhttpc:1.3.0 public_key:0.21 asn1:2.0.4 kernel:2.16.4 crypto:3.2 sasl:2.3.4 stdlib:1.19.4 os_mon:2.2.14 ale:4.0.0-1650-rel-enterprise inets:5.9.8 ns_server:4.0.0-1650-rel-enterprise ssl:5.3.3] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [

{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
StatisticsManager2015/03/25 18:17:46.974669 [INFO] highseqno_map=map[42:29 193:5 312:34 1:34 502:7 507:32 106:29 131:29 293:31 418:9 451:34 40:4 185:9 265:29 279:9 347:29 447:5 35:34 83:32 88:7 222:30 156:10 211:11 316:6 315:8 328:32 390:6 439:9 179:28 253:30 254:6 269:9 366:9 393:8 400:28 77:5 182:12 204:30 350:10 121:34 226:7 323:7 491:8 97:8 223:31 324:11 385:7 433:8 449:10 476:6 57:32 78:31 352:8 398:8 459:34 118:30 123:8 230:34 296:8 450:28 487:31 4:7 128:11 270:30 282:34 110:6 135:7 186:34 192:7 421:6 334:34 364:34 423:35 23:7 60:10 71:34 159:30 20:30 266:8 341:31 38:7 127:30 427:9 2:6 283:29 103:6 148:5 479:35 481:34 73:34 191:8 276:34 420:8 34:28 300:30 381:8 397:31 224:32 234:8 237:7 299:28 455:9 462:9 484:7 21:30 61:7 274:33 329:29 336:8 32:8 49:34 271:30 314:7 134:11 177:7 465:34 353:12 242:32 281:6 286:9 301:32 18:29 382:34 460:29 95:11 145:29 202:34 199:6 241:5 243:28 287:7 463:8 94:6 167:30 175:29 176:9 431:30 495:34 415:31 480:29 503:10 483:7 11:7 369:29 404:8 457:7 144:34 189:29 375:30 399:5 403:8 492:7 68:5 108:30 170:8 278:8 384:7 214:35 321:29 331:10 339:29 302:10 67:7 258:7 280:10 288:8 272:7 297:5 506:28 285:30 295:10 58:10 91:34 236:10 244:34 98:29 453:30 142:7 221:8 346:32 119:34 443:34 28:30 126:30 294:7 197:30 86:8 247:7 497:8 508:30 320:34 345:6 354:34 387:32 76:8 425:34 7:30 205:30 290:32 466:9 33:7 149:8 219:6 372:12 405:7 473:34 162:8 164:5 231:30 238:31 456:11 45:34 143:9 310:34 434:28 84:32 359:6 440:12 12:9 139:28 235:7 263:31 251:29 267:8 343:8 309:6 396:30 505:7 509:34 120:29 146:8 195:28 248:7 408:29 436:29 485:6 494:30 55:30 332:7 333:8 392:10 165:8 17:8 184:8 482:8 187:28 15:34 163:11 198:11 446:8 240:8 311:32 65:32 125:6 181:31 227:12 16:8 489:32 289:10 355:29 410:7 414:30 25:7 172:9 173:6 188:35 104:7 216:34 101:34 112:30 349:32 56:29 171:5 201:8 325:6 389:34 229:11 277:30 368:34 373:6 169:28 207:10 245:30 380:6 477:11 10:11 22:9 319:31 467:7 19:34 44:31 47:10 252:31 93:30 218:10 298:34 510:11 406:30 30:6 72:28 89:11 215:29 124:6 413:11 430:30 437:35 36:31 39:6 63:34 79:30 454:8 66:6 178:34 256:33 313:29 470:31 5:9 85:34 109:30 217:28 395:34 426:6 444:31 448:5 9:33 59:8 122:12 304:32 461:35 233:29 26:29 48:29 344:7 412:7 501:31 416:28 136:8 161:28 268:7 383:30 424:28 379:9 409:34 417:34 464:28 249:8 291:29 305:29 116:5 335:31 428:7 441:8 378:8 435:34 498:29 114:5 157:6 206:7 212:8 342:5 458:28 166:30 306:8 330:8 357:30 130:34 200:7 356:30 239:30 260:11 432:5 3:10 75:8 132:31 228:7 469:7 493:10 504:12 180:30 318:30 351:5 401:32 210:7 374:30 6:30 41:8 158:34 203:28 442:28 24:5 43:32 340:30 388:30 365:30 391:10 486:30 511:7 13:8 74:10 250:34 292:34 419:8 438:6 472:28 8:29 92:31 140:34 371:7 174:35 183:7 402:11 90:30 411:11 29:34 46:6 232:34 327:31 147:10 168:34 500:30 37:30 358:6 499:34 475:7 82:29 153:28 246:10 452:30 209:28 273:11 468:10 87:7 196:35 308:10 370:9 113:33 155:7 445:30 361:5 96:9 100:30 105:9 326:30 27:33 50:5 81:8 322:11 362:33 478:30 64:29 129:7 275:29 337:10 490:5 62:32 255:7 264:34 474:5 53:10 102:8 190:6 52:7 80:10 422:29 137:11 220:9 225:28 394:29 213:9 303:7 367:5 377:29 360:8 429:12 496:6 0:29 115:8 160:34 261:6 107:34 151:30 152:32 471:30 376:33 14:30 51:8 138:32 259:6 407:34 488:28 111:12 154:7 208:34 386:28 133:30 194:34 307:4 338:34 54:32 69:10 99:33 117:9 150:31 257:29 284:30 348:34 70:31 141:30 363:30 31:11 262:34 317:7]
StatisticsManager2015/03/25 18:17:46.974822 [INFO] total_doc=10000, docs_processed=10000, changes_left=0
StatisticsManager2015/03/25 18:17:46.975357 [INFO] Stats for pipeline bb3498305c12d847e54445ec71d21ff0/default/default-305467188 {"CkptMgr": {"num_checkpoints": 7, "num_failedckpts": 0, "time_committing": {"count": 7, "max": 142534, "mean": 124745, "min": 96316}}, "Errors": "[]", "Overview": {"bandwidth_usage": 0, "changes_left": 0, "data_replicated": 2854445, "docs_checked": 10000, "docs_failed_cr_source": 5000, "docs_filtered": 0, "docs_opt_repd": 0, "docs_processed": 10000, "docs_received_from_dcp": 10000, "docs_rep_queue": 0, "docs_written": 5000, "num_checkpoints": 7, "num_failedckpts": 0, "rate_doc_checks": 166.66666666666666, "rate_doc_opt_repd": 0, "rate_received_from_dcp": 0, "rate_replicated": 0, "size_rep_queue": 0, "time_committing": 124745, "wtavg_docs_latency": 0, "wtavg_meta_latency": 0}, "Progress": "Pipeline is running", "Status": "Replicating", "XDCRRouter": {"docs_filtered": 0}, "dcp_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.45:11210_0": {"docs_received_from_dcp": 5000}, "dcp_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.45:11210_1": {"docs_received_from_dcp": 5000}, "xmem_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.47:11210_0": {"data_replicated": 1426654, "docs_failed_cr_source": 2501, "docs_opt_repd": 0, "docs_rep_queue": 0, "docs_written": 2499, "size_rep_queue": 0}, "xmem_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.47:11210_1": {"data_replicated": 1427791, "docs_failed_cr_source": 2499, "docs_opt_repd": 0, "docs_rep_queue": 0, "docs_written": 2501, "size_rep_queue": 0}}

StatisticsManager2015/03/25 18:17:46.975426 [INFO] Xmem xmem_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.47:11210_0 state =2 connType=SSLOverMem received 5000 items, sent 5000 items, 0 items waiting to confirm, 0 in queue
StatisticsManager2015/03/25 18:17:46.975461 [INFO] Xmem xmem_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.47:11210_1 state =2 connType=SSLOverMem received 5000 items, sent 5000 items, 0 items waiting to confirm, 0 in queue
StatisticsManager2015/03/25 18:17:46.975500 [INFO] Rounter Router_dcp_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.45:11210_0 = map[xmem_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.47:11210_0:5000]
StatisticsManager2015/03/25 18:17:46.975544 [INFO] Dcp dcp_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.45:11210_0 streamed 5000 items. [] streams inactive
StatisticsManager2015/03/25 18:17:46.975597 [INFO] Rounter Router_dcp_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.45:11210_1 = map[xmem_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.47:11210_1:5000]
StatisticsManager2015/03/25 18:17:46.975639 [INFO] Dcp dcp_bb3498305c12d847e54445ec71d21ff0/default/default_172.23.106.45:11210_1 streamed 5000 items. [] streams inactive
StatisticsManager2015/03/25 18:17:47.159874 [INFO] highseqno_map=map[160:34 423:35 389:34 74:10 256:33 367:5 378:8 416:28 438:6 176:9 355:29 58:10 443:34 466:9 26:29 36:31 186:34 280:10 281:6 482:8 44:31 182:12 324:11 350:10 366:9 431:30 163:11 260:11 456:11 48:29 230:34 158:34 348:34 50:5 65:32 393:8 229:11 263:31 419:8 510:11 249:8 349:32 294:7 341:31 27:33 97:8 319:31 35:34 116:5 206:7 223:31 238:31 257:29 53:10 165:8 472:28 241:5 437:35 146:8 479:35 255:7 321:29 354:34 357:30 445:30 157:6 197:30 399:5 436:29 99:33 211:11 214:35 33:7 205:30 278:8 408:29 461:35 13:8 30:6 159:30 242:32 308:10 333:8 342:5 480:29 127:30 133:30 339:29 415:31 458:28 103:6 286:9 226:7 376:33 426:6 147:10 195:28 81:8 138:32 283:29 307:4 42:29 64:29 122:12 191:8 476:6 68:5 93:30 6:30 274:33 245:30 219:6 233:29 403:8 347:29 386:28 326:30 448:5 178:34 282:34 248:7 315:8 90:30 170:8 484:7 440:12 459:34 454:8 465:34 213:9 272:7 188:35 266:8 7:30 111:12 402:11 196:35 306:8 325:6 39:6 123:8 240:8 169:28 210:7 351:5 384:7 105:9 106:29 236:10 421:6 492:7 0:29 80:10 254:6 299:28 4:7 152:32 131:29 148:5 486:30 23:7 83:32 112:30 156:10 177:7 338:34 353:12 96:9 100:30 54:32 273:11 314:7 364:34 388:30 14:30 37:30 193:5 334:34 104:7 126:30 247:7 140:34 237:7 397:31 444:31 121:34 142:7 407:34 117:9 246:10 305:29 385:7 175:29 312:34 125:6 173:6 398:8 405:7 497:8 137:11 392:10 79:30 447:5 11:7 12:9 329:29 208:34 264:34 293:31 387:32 395:34 234:8 253:30 452:30 124:6 184:8 222:30 309:6 473:34 86:8 207:10 270:30 8:29 132:31 28:30 95:11 114:5 151:30 220:9 450:28 19:34 20:30 337:10 414:30 467:7 41:8 258:7 288:8 322:11 420:8 509:34 199:6 265:29 155:7 335:31 418:9 34:28 45:34 316:6 318:30 500:30 63:34 295:10 352:8 373:6 71:34 203:28 332:7 469:7 494:30 3:10 153:28 296:8 84:32 161:28 118:30 292:34 303:7 313:29 501:31 10:11 59:8 276:34 369:29 404:8 453:30 187:28 228:7 189:29 91:34 411:11 185:9 394:29 396:30 172:9 310:34 406:30 328:32 336:8 271:30 330:8 29:34 217:28 422:29 424:28 77:5 87:7 166:30 167:30 135:7 164:5 289:10 505:7 57:32 85:34 218:10 380:6 200:7 202:34 209:28 275:29 345:6 485:6 52:7 150:31 251:29 430:30 17:8 183:7 372:12 66:6 113:33 243:28 381:8 511:7 168:34 201:8 493:10 31:11 464:28 98:29 180:30 204:30 363:30 40:4 162:8 290:32 375:30 82:29 108:30 446:8 1:34 119:34 134:11 449:10 481:34 69:10 89:11 129:7 432:5 383:30 417:34 451:34 468:10 471:30 231:30 239:30 470:31 496:6 51:8 302:10 194:34 235:7 9:33 144:34 377:29 477:11 287:7 360:8 474:5 2:6 457:7 370:9 139:28 215:29 390:6 439:9 49:34 67:7 475:7 488:28 427:9 441:8 483:7 5:9 412:7 225:28 504:12 46:6 149:8 442:28 508:30 21:30 43:32 409:34 507:32 62:32 400:28 179:28 320:34 24:5 25:7 268:7 362:33 374:30 107:34 174:35 401:32 190:6 261:6 232:34 262:34 379:9 120:29 198:11 92:31 252:31 429:12 47:10 72:28 259:6 269:9 304:32 425:34 428:7 478:30 110:6 171:5 489:32 212:8 327:31 359:6 371:7 491:8 109:30 181:31 102:8 130:34 250:34 331:10 38:7 94:6 301:32 101:34 216:34 267:8 368:34 434:28 463:8 32:8 115:8 358:6 55:30 141:30 244:34 344:7 490:5 143:9 154:7 221:8 433:8 298:34 356:30 455:9 502:7 506:28 22:9 279:9 435:34 495:34 297:5 391:10 300:30 323:7 413:11 78:31 284:30 462:9 60:10 460:29 340:30 343:8 70:31 311:32 382:34 499:34 73:34 227:12 88:7 224:32 503:10 15:34 75:8 410:7 16:8 145:29 277:30 317:7 18:29 136:8 285:30 498:29 61:7 128:11 361:5 56:29 76:8 346:32 365:30 487:31 192:7 291:29]
StatisticsManager2015/03/25 18:17:47.160031 [INFO] total_doc=10000, docs_processed=10000, changes_left=0
StatisticsManager2015/03/25 18:17:47.160962 [INFO] Stats for pipeline bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1-666935496 {"CkptMgr": {"num_checkpoints": 7, "num_failedckpts": 0, "time_committing": {"count": 7, "max": 142072, "mean": 124748.28571428571, "min": 95573}}, "Errors": "[]", "Overview": {"bandwidth_usage": 0, "changes_left": 0, "data_replicated": 2854445, "docs_checked": 10000, "docs_failed_cr_source": 5000, "docs_filtered": 0, "docs_opt_repd": 0, "docs_processed": 10000, "docs_received_from_dcp": 10000, "docs_rep_queue": 0, "docs_written": 5000, "num_checkpoints": 7, "num_failedckpts": 0, "rate_doc_checks": 166.66666666666666, "rate_doc_opt_repd": 0, "rate_received_from_dcp": 0, "rate_replicated": 0, "size_rep_queue": 0, "time_committing": 124748, "wtavg_docs_latency": 0, "wtavg_meta_latency": 0}, "Progress": "Pipeline is running", "Status": "Replicating", "XDCRRouter": {"docs_filtered": 0}, "dcp_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.45:11210_0": {"docs_received_from_dcp": 5000}, "dcp_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.45:11210_1": {"docs_received_from_dcp": 5000}, "xmem_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.47:11210_0": {"data_replicated": 1426654, "docs_failed_cr_source": 2501, "docs_opt_repd": 0, "docs_rep_queue": 0, "docs_written": 2499, "size_rep_queue": 0}, "xmem_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.47:11210_1": {"data_replicated": 1427791, "docs_failed_cr_source": 2499, "docs_opt_repd": 0, "docs_rep_queue": 0, "docs_written": 2501, "size_rep_queue": 0}}

StatisticsManager2015/03/25 18:17:47.161032 [INFO] Xmem xmem_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.47:11210_0 state =2 connType=SSLOverMem received 5000 items, sent 5000 items, 0 items waiting to confirm, 0 in queue
StatisticsManager2015/03/25 18:17:47.161066 [INFO] Xmem xmem_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.47:11210_1 state =2 connType=SSLOverMem received 5000 items, sent 5000 items, 0 items waiting to confirm, 0 in queue
StatisticsManager2015/03/25 18:17:47.161105 [INFO] Rounter Router_dcp_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.45:11210_1 = map[xmem_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.47:11210_1:5000]
StatisticsManager2015/03/25 18:17:47.161149 [INFO] Dcp dcp_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.45:11210_1 streamed 5000 items. [] streams inactive
StatisticsManager2015/03/25 18:17:47.161207 [INFO] Rounter Router_dcp_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.45:11210_0 = map[xmem_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.47:11210_0:5000]
StatisticsManager2015/03/25 18:17:47.161247 [INFO] Dcp dcp_bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1_172.23.106.45:11210_0 streamed 5000 items. [] streams inactive
GenericSupervisor2015/03/25 18:17:48.380038 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:17:48.380099 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
RemoteClusterService2015/03/25 18:17:48.489530 [INFO] Pool.Nodes=[{262144 active http://172.23.106.47:8092/ 172.23.106.47:8091 map[cmd_get:0 couch_docs_actual_disk_size:1.0995255e+08 couch_docs_data_size:9.9510272e+07 ep_bg_fetched:0 get_hits:0 vb_replica_curr_items:20000 couch_views_actual_disk_size:0 couch_views_data_size:0 curr_items:20000 curr_items_tot:40000 mem_used:1.12125744e+08 ops:0] 3104 3104 1.61814528e+09 4.069695488e+09 x86_64-unknown-linux-gnu map[httpsMgmt:18091 httpsCAPI:18092 proxy:11211 direct:11210 sslProxy:11214] healthy 10280 4.0.0-1650-rel-enterprise true} {262144 active http://172.23.106.48:8092/ 172.23.106.48:8091 map[curr_items_tot:40000 get_hits:0 mem_used:1.06477128e+08 ops:0 couch_docs_actual_disk_size:1.06590041e+08 couch_views_actual_disk_size:0 couch_views_data_size:0 curr_items:20000 ep_bg_fetched:0 vb_replica_curr_items:20000 cmd_get:0 couch_docs_data_size:0] 3104 3104 2.33678848e+09 4.069695488e+09 x86_64-unknown-linux-gnu map[proxy:11211 direct:11210 sslProxy:11214 httpsMgmt:18091 httpsCAPI:18092] healthy 1245 4.0.0-1650-rel-enterprise false}]
RemoteClusterService2015/03/25 18:17:48.491132 [INFO] Remote cluster reference remoteCluster/bb3498305c12d847e54445ec71d21ff0 is cached, cache =&{remoteCluster/bb3498305c12d847e54445ec71d21ff0 [172.23.106.48:8091] 0xc208fb38c0}
Utils2015/03/25 18:17:48.544031 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password} {map[lhttpc:1.3.0 os_mon:2.2.14 public_key:0.21 ale:4.0.0-1650-rel-enterprise crypto:3.2 sasl:2.3.4 stdlib:1.19.4 asn1:2.0.4 kernel:2.16.4 inets:5.9.8 ns_server:4.0.0-1650-rel-enterprise ssl:5.3.3] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}

]}}
Utils2015/03/25 18:17:48.936339 [INFO] client={http://Administrator:password@172.23.106.47:8091

{Administrator password} {map[ssl:5.3.3 sasl:2.3.4 os_mon:2.2.14 asn1:2.0.4 kernel:2.16.4 ale:4.0.0-1650-rel-enterprise inets:5.9.8 ns_server:4.0.0-1650-rel-enterprise stdlib:1.19.4 lhttpc:1.3.0 public_key:0.21 crypto:3.2] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
ClusterInfoService2015/03/25 18:17:49.487219 [INFO] version=[3 0], effectiveVersion=12288
ToplogyChangeDetector2015/03/25 18:17:49.487528 [INFO] Detected that remote cluster 172.23.106.47:8091 has upgraded to 3.0 or above
ToplogyChangeDetector2015/03/25 18:17:49.487547 [INFO] validateSourceTopology...
GenericSupervisor2015/03/25 18:17:52.380296 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:17:52.380374 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
Utils2015/03/25 18:17:54.518041 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password}

{map[sasl:2.3.4 lhttpc:1.3.0 public_key:0.21 kernel:2.16.4 ale:4.0.0-1650-rel-enterprise inets:5.9.8 ns_server:4.0.0-1650-rel-enterprise crypto:3.2 ssl:5.3.3 os_mon:2.2.14 asn1:2.0.4 stdlib:1.19.4] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [

{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
PipelineManager2015/03/25 18:17:54.789166 [INFO] Replication Status = map[bb3498305c12d847e54445ec71d21ff0/default/default:name={bb3498305c12d847e54445ec71d21ff0/default/default}, status={Replicating}, errors={[]}, progress={Pipeline is running}
bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1:name={bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1}, status={Replicating}, errors={[]}, progress={Pipeline is running}
]
GenericSupervisor2015/03/25 18:17:56.380680 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:17:56.380749 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
RemoteClusterService2015/03/25 18:17:59.706674 [INFO] Refresh remote cluster reference remoteCluster/bb3498305c12d847e54445ec71d21ff0
RemoteClusterService2015/03/25 18:17:59.706696 [INFO] Remote Cluster reference 172.23.106.47:8091 need to be updated
Utils2015/03/25 18:17:59.710825 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password} {map[os_mon:2.2.14 public_key:0.21 kernel:2.16.4 inets:5.9.8 ssl:5.3.3 stdlib:1.19.4 lhttpc:1.3.0 asn1:2.0.4 ale:4.0.0-1650-rel-enterprise ns_server:4.0.0-1650-rel-enterprise crypto:3.2 sasl:2.3.4] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}

]}}
RemoteClusterService2015/03/25 18:17:59.916832 [INFO] Pool.Nodes=[

{262144 active http://172.23.106.47:8092/ 172.23.106.47:8091 map[couch_views_actual_disk_size:0 couch_views_data_size:0 mem_used:1.12125744e+08 ops:0 vb_replica_curr_items:20000 cmd_get:0 couch_docs_actual_disk_size:1.0995255e+08 couch_docs_data_size:9.9510272e+07 get_hits:0 curr_items:20000 curr_items_tot:40000 ep_bg_fetched:0] 3104 3104 1.673084928e+09 4.069695488e+09 x86_64-unknown-linux-gnu map[sslProxy:11214 httpsMgmt:18091 httpsCAPI:18092 proxy:11211 direct:11210] healthy 10290 4.0.0-1650-rel-enterprise true}

{262144 active http://172.23.106.48:8092/ 172.23.106.48:8091 map[ep_bg_fetched:0 get_hits:0 mem_used:1.06476984e+08 ops:0 vb_replica_curr_items:20000 couch_views_actual_disk_size:0 couch_views_data_size:0 curr_items:20000 curr_items_tot:40000 cmd_get:0 couch_docs_actual_disk_size:1.06590042e+08 couch_docs_data_size:0] 3104 3104 2.433470464e+09 4.069695488e+09 x86_64-unknown-linux-gnu map[sslProxy:11214 httpsMgmt:18091 httpsCAPI:18092 proxy:11211 direct:11210] healthy 1255 4.0.0-1650-rel-enterprise false}

]
RemoteClusterService2015/03/25 18:17:59.917204 [INFO] Remote cluster reference remoteCluster/bb3498305c12d847e54445ec71d21ff0 is cached, cache =&

{remoteCluster/bb3498305c12d847e54445ec71d21ff0 [172.23.106.48:8091] 0xc2086ebe60}

Utils2015/03/25 18:17:59.923280 [INFO] client={http://Administrator:password@172.23.106.47:8091

{Administrator password} {map[ssl:5.3.3 os_mon:2.2.14 asn1:2.0.4 kernel:2.16.4 inets:5.9.8 crypto:3.2 sasl:2.3.4 stdlib:1.19.4 lhttpc:1.3.0 public_key:0.21 ale:4.0.0-1650-rel-enterprise ns_server:4.0.0-1650-rel-enterprise] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}]}}
ClusterInfoService2015/03/25 18:18:00.033485 [INFO] version=[3 0], effectiveVersion=12288
ToplogyChangeDetector2015/03/25 18:18:00.033831 [INFO] Detected that remote cluster 172.23.106.47:8091 has upgraded to 3.0 or above
ToplogyChangeDetector2015/03/25 18:18:00.033999 [INFO] validateSourceTopology...
GenericSupervisor2015/03/25 18:18:00.381039 [ERROR] Heartbeat timeout in supervisor ReplicationManagerSupervisor! not_yet_resp_count=1
GenericSupervisor2015/03/25 18:18:00.381105 [INFO] Send heartbeat failed for AdminportSupervisor, err=Last heart beat msg has not been processed
Utils2015/03/25 18:18:01.067500 [INFO] client={http://Administrator:password@172.23.106.47:8091 {Administrator password}

{map[os_mon:2.2.14 public_key:0.21 asn1:2.0.4 inets:5.9.8 ssl:5.3.3 stdlib:1.19.4 lhttpc:1.3.0 kernel:2.16.4 ale:4.0.0-1650-rel-enterprise ns_server:4.0.0-1650-rel-enterprise crypto:3.2 sasl:2.3.4] 4.0.0-1650-rel-enterprise true bb3498305c12d847e54445ec71d21ff0 [

{default /poolsStreaming/default?uuid=bb3498305c12d847e54445ec71d21ff0 /pools/default?uuid=bb3498305c12d847e54445ec71d21ff0}

]}}
HttpServer2015/03/25 18:18:01.659858 [INFO] Request received from ServeHTTP. r=&

{DELETE /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1 HTTP/1.1 1 1 map[Authorization:[Basic QWRtaW5pc3RyYXRvcjpwYXNzd29yZA==] Menelaus_auth-Token:[undefined] Menelaus_auth-User:[Administrator] Content-Length:[0] Accept:[*/*] Accept-Encoding:[identity] Content-Type:[application/x-www-form-urlencoded] Menelaus_auth-Role:[admin] User-Agent:[Python-httplib2/$Rev: 259 $]] 0xbc7300 0 [] false 172.23.106.45:8091 map[] map[] <nil> map[] 127.0.0.1:34970 /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1 <nil>}

with path, /controller/cancelXDCR/bb3498305c12d847e54445ec71d21ff0/sasl_bucket_1/sasl_bucket_1 and method, DELETE
HttpServer2015/03/25 18:18:02.221314 [INFO] Request received from ServeHTTP. r=&

{GET /stats/buckets/default HTTP/1.1 1 1 map[Accept:[application/json] Authorization:[Basic QDowNzc5MDI5OGI1OGM1OWI4NzRhZWFkYWY1ZjdjMzMyMw==]] 0xbc7300 0 [] false 127.0.0.1:9998 map[] map[] <nil> map[] 127.0.0.1:35189 /stats/buckets/default <nil>}

with path, /stats/buckets/default and method, GET
HttpServer2015/03/25 18:18:02.221455 [INFO] Request received from ServeHTTP. r=&

{GET /stats/buckets/sasl_bucket_1 HTTP/1.1 1 1 map[Authorization:[Basic QDowNzc5MDI5OGI1OGM1OWI4NzRhZWFkYWY1ZjdjMzMyMw==] Accept:[application/json]] 0xbc7300 0 [] false 127.0.0.1:9998 map[] map[] <nil> map[] 127.0.0.1:40331 /stats/buckets/sasl_bucket_1 <nil>}

with path, /stats/buckets/sasl_bucket_1 and method, GET
ReplicationSpecService2015/03/25 18:18:03.139963 [INFO] metakvCallback called on path = /replicationSpec/bb3498305c12d847e54445ec71d21ff0/default/default
ReplicationManager2015/03/25 18:18:03.140004 [INFO] specChangedCallback called on id = bb3498305c12d847e54445ec71d21ff0/default/default
ReplicationManager2015/03/25 18:18:03.140015 [INFO] Stopping pipeline bb3498305c12d847e54445ec71d21ff0/default/default since the replication spec has been deleted
PipelineManager2015/03/25 18:18:03.140030 [INFO] Try to stop the pipeline bb3498305c12d847e54445ec71d21ff0/default/default
GenericPipeline2015/03/25 18:18:03.140050 [INFO] stoppping pipeline bb3498305c12d847e54445ec71d21ff0/default/default-305467188
PipelineRuntimeCtx2015/03/25 18:18:03.140067 [INFO] Pipeline context is stopping...
GenericSupervisor2015/03/25 18:18:03.140079 [INFO] Stopping supervisor PipelineSupervisor_bb3498305c12d847e54445ec71d21ff0/default/default.
GenericSupervisor2015/03/25 18:18:03.140431 [INFO] server is stopped per request sent at 2015-03-25 18:18:03.140386 -0700 PDT
GenericSupervisor2015/03/25 18:18:03.140450 [INFO] Supervisor PipelineSupervisor_bb3498305c12d847e54445ec71d21ff0/default/default exited
GenericSupervisor2015/03/25 18:18:03.140460 [INFO] Stopped supervisor PipelineSupervisor_bb3498305c12d847e54445ec71d21ff0/default/default.
GenericSupervisor2015/03/25 18:18:03.140467 [INFO] Removing child PipelineSupervisor_bb3498305c12d847e54445ec71d21ff0/default/default from supervisor PipelineMasterSupervisor
ReplicationManager2015/03/25 18:18:03.548471 [INFO] Replication specification bb3498305c12d847e54445ec71d21ff0/default/default is deleted
ReplicationManager2015/03/25 18:18:03.548511 [INFO] Pipeline bb3498305c12d847e54445ec71d21ff0/default/default is deleted

And we are trying to Delete checkpoints soon after and metakv recursive delete fails-

CheckpointService2015/03/25 18:18:03.549085 [INFO] DelCheckpointsDocs...
:
:
MetadataService2015/03/25 18:18:22.045066 [ERROR] metakv.RecursiveDelete failed. catalogKey=ckpt/bb3498305c12d847e54445ec71d21ff0/default/default, err=Rev mismatch, num_of_retry=1

Attaching logs.