Go-XDCR: Checkpointing doesn't happen after destination bucket is deleted and recreated

Build
------
3.5.0-1270

Testcase
------------

/testrunner -i INI_FILE.ini -p enable_goxdcr=True,checkpoint_interval=60 -t xdcr.checkpointXDCR.XDCRCheckpointUnitTest.test_failover, rdirection=unidirection,topology=chain,replication_type=xmem,failover=source

Steps
-------
1. C1 [.170,.171] --> C2 [.120,.169]
2. Add 2 keys to C1 at an interval of 70s, checkpoints not recorded (not sure why)
3. Delete and recreate bucket on C2.
4. Add another key on C1 after 70s. Since vb_uuid changed, we expect checkpointing to fail.
5. Add another key on C1 after 70s. Make sure checkpointing happens. It fails here though.

[2015-02-17 18:14:41,774] - [checkpointXDCR:252] INFO - Remote failover log: [118290900338202, 1]
[2015-02-17 18:14:41,774] - [checkpointXDCR:253] INFO - ################ New mutation:2 ##################
[2015-02-17 18:14:41,775] - [checkpointXDCR:236] INFO - Loaded key pymc1108 onto vb0 in 172.23.107.170
[2015-02-17 18:14:41,776] - [checkpointXDCR:237] INFO - deleted, flags, exp, rev_id, cas for key pymc1108 = (0, 0, 0, 1, 1424225681779326976)
[2015-02-17 18:14:41,865] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:14:41,980] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:14:42,056] - [remote_util:155] INFO - connecting to 172.23.107.120 with username : root password : couchbase ssh_key:
[2015-02-17 18:14:42,194] - [remote_util:188] INFO - Connected to 172.23.107.120
[2015-02-17 18:14:42,422] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/cpuinfo
[2015-02-17 18:14:42,511] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:42,512] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: df -Th
[2015-02-17 18:14:42,584] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:42,584] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/meminfo
[2015-02-17 18:14:42,677] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:42,677] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname
[2015-02-17 18:14:42,748] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:42,749] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname -d
[2015-02-17 18:14:42,844] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:42,846] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_commit_for_checkpoint" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:14:42,934] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:42,935] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_commit_for_checkpoint 200" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:14:43,027] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:14:43,029] - [checkpointXDCR:168] INFO - 15
[2015-02-17 18:14:43,029] - [checkpointXDCR:171] INFO - Checkpoint on this node (this run): 0
[2015-02-17 18:14:43,130] - [checkpointXDCR:208] INFO - Checkpointing did not happen: last recorded call :19 , now :19
[2015-02-17 18:14:43,130] - [checkpointXDCR:263] INFO - Checkpointing failed - may not be an error if vb_uuid changed
[2015-02-17 18:14:44,525] - [bucket_helper:226] INFO - waiting for bucket deletion to complete....
[2015-02-17 18:14:44,531] - [rest_client:123] INFO - node 172.23.107.120 existing buckets : []
[2015-02-17 18:14:45,552] - [rest_client:1601] INFO - http://172.23.107.120:8091/pools/default/buckets with param: bucketType=membase&evictionPolicy=valueOnly&threadsNumber=3&ramQuotaMB=2069&proxyPort=11211&authType=sasl&name=default&flushEnabled=1&replicaNumber=1&replicaIndex=1&saslPassword=None
[2015-02-17 18:14:45,568] - [rest_client:1623] INFO - 0.02 seconds to create bucket default
[2015-02-17 18:14:45,568] - [bucket_helper:305] INFO - waiting for memcached bucket : default in 172.23.107.120 to accept set ops
[2015-02-17 18:14:46,841] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:14:46,942] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:14:47,086] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:14:47,199] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:14:47,874] - [task:224] INFO - bucket 'default' was created with per node RAM quota: 2069
[2015-02-17 18:14:47,986] - [data_helper:295] INFO - creating direct client 172.23.107.170:11210 default
[2015-02-17 18:14:48,082] - [data_helper:295] INFO - creating direct client 172.23.107.171:11210 default
[2015-02-17 18:14:48,185] - [xdcrnewbasetests:2818] INFO - sleep for 70 secs. ...
[2015-02-17 18:15:58,351] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:15:58,454] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:15:58,539] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:15:58,815] - [data_helper:295] INFO - creating direct client 172.23.107.170:11210 default
[2015-02-17 18:15:58,895] - [data_helper:295] INFO - creating direct client 172.23.107.171:11210 default
[2015-02-17 18:15:59,001] - [data_helper:295] INFO - creating direct client 172.23.107.170:11210 default
[2015-02-17 18:15:59,179] - [checkpointXDCR:251] INFO - Local failover log: [148330965689814, 2]
[2015-02-17 18:15:59,180] - [checkpointXDCR:252] INFO - Remote failover log: [148747363266383, 0]
[2015-02-17 18:15:59,180] - [checkpointXDCR:253] INFO - ################ New mutation:3 ##################
[2015-02-17 18:15:59,181] - [checkpointXDCR:236] INFO - Loaded key pymc2329 onto vb0 in 172.23.107.170
[2015-02-17 18:15:59,183] - [checkpointXDCR:237] INFO - deleted, flags, exp, rev_id, cas for key pymc2329 = (0, 0, 0, 1, 1424225759185403904)
[2015-02-17 18:15:59,256] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:15:59,372] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:15:59,446] - [remote_util:155] INFO - connecting to 172.23.107.120 with username : root password : couchbase ssh_key:
[2015-02-17 18:15:59,583] - [remote_util:188] INFO - Connected to 172.23.107.120
[2015-02-17 18:15:59,814] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/cpuinfo
[2015-02-17 18:15:59,907] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:15:59,907] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: df -Th
[2015-02-17 18:15:59,977] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:15:59,977] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/meminfo
[2015-02-17 18:16:00,067] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:00,068] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname
[2015-02-17 18:16:00,139] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:00,140] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname -d
[2015-02-17 18:16:00,240] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:00,241] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_commit_for_checkpoint" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:16:00,281] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:00,281] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_commit_for_checkpoint 200" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:16:00,361] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:00,362] - [checkpointXDCR:168] INFO - 15
[2015-02-17 18:16:00,362] - [checkpointXDCR:171] INFO - Checkpoint on this node (this run): 0
[2015-02-17 18:16:00,363] - [checkpointXDCR:204] INFO - _commit_for_checkpoint was NOT successful: last recorded failure :4 , now :5
[2015-02-17 18:16:00,363] - [checkpointXDCR:263] INFO - Checkpointing failed - may not be an error if vb_uuid changed
[2015-02-17 18:16:00,364] - [checkpointXDCR:492] INFO - Checkpointing failed as expected after remote uuid change, not a bug
[2015-02-17 18:16:00,437] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:16:00,551] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:16:00,631] - [remote_util:155] INFO - connecting to 172.23.107.120 with username : root password : couchbase ssh_key:
[2015-02-17 18:16:00,770] - [remote_util:188] INFO - Connected to 172.23.107.120
[2015-02-17 18:16:00,998] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/cpuinfo
[2015-02-17 18:16:01,096] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,097] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: df -Th
[2015-02-17 18:16:01,164] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,165] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/meminfo
[2015-02-17 18:16:01,286] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,287] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname
[2015-02-17 18:16:01,378] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,379] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname -d
[2015-02-17 18:16:01,454] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,455] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_pre_replicate" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:16:01,540] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,540] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_pre_replicate 200" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:16:01,692] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:16:01,693] - [checkpointXDCR:217] INFO - _pre_replicate was successful: last recorded success :8191 , now :8703
[2015-02-17 18:16:01,693] - [checkpointXDCR:497] INFO - _pre_replicate following the failed checkpoint was successful
[2015-02-17 18:16:01,747] - [data_helper:295] INFO - creating direct client 172.23.107.170:11210 default
[2015-02-17 18:16:01,839] - [data_helper:295] INFO - creating direct client 172.23.107.171:11210 default
[2015-02-17 18:16:01,913] - [xdcrnewbasetests:2818] INFO - sleep for 70 secs. ...
[2015-02-17 18:17:12,057] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:17:12,143] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:17:12,220] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:17:12,491] - [data_helper:295] INFO - creating direct client 172.23.107.170:11210 default
[2015-02-17 18:17:12,575] - [data_helper:295] INFO - creating direct client 172.23.107.171:11210 default
[2015-02-17 18:17:12,673] - [data_helper:295] INFO - creating direct client 172.23.107.170:11210 default
[2015-02-17 18:17:12,823] - [checkpointXDCR:251] INFO - Local failover log: [148330965689814, 3]
[2015-02-17 18:17:12,823] - [checkpointXDCR:252] INFO - Remote failover log: [148747363266383, 3]
[2015-02-17 18:17:12,823] - [checkpointXDCR:253] INFO - ################ New mutation:4 ##################
[2015-02-17 18:17:12,824] - [checkpointXDCR:236] INFO - Loaded key pymc4019 onto vb0 in 172.23.107.170
[2015-02-17 18:17:12,825] - [checkpointXDCR:237] INFO - deleted, flags, exp, rev_id, cas for key pymc4019 = (0, 0, 0, 1, 1424225832828338176)
[2015-02-17 18:17:12,896] - [data_helper:295] INFO - creating direct client 172.23.107.120:11210 default
[2015-02-17 18:17:12,982] - [data_helper:295] INFO - creating direct client 172.23.107.169:11210 default
[2015-02-17 18:17:13,066] - [remote_util:155] INFO - connecting to 172.23.107.120 with username : root password : couchbase ssh_key:
[2015-02-17 18:17:13,207] - [remote_util:188] INFO - Connected to 172.23.107.120
[2015-02-17 18:17:13,405] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/cpuinfo
[2015-02-17 18:17:13,487] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,488] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: df -Th
[2015-02-17 18:17:13,575] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,576] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: sudo cat /proc/meminfo
[2015-02-17 18:17:13,656] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,657] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname
[2015-02-17 18:17:13,722] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,723] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: hostname -d
[2015-02-17 18:17:13,792] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,794] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_commit_for_checkpoint" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:17:13,887] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,888] - [remote_util:1800] INFO - running command.raw on 172.23.107.120: grep "POST /_commit_for_checkpoint 200" "/opt/couchbase/var/lib/couchbase/logs/couchdb.log" | wc -l
[2015-02-17 18:17:13,980] - [remote_util:1837] INFO - command executed successfully
[2015-02-17 18:17:13,980] - [checkpointXDCR:168] INFO - 15
[2015-02-17 18:17:13,981] - [checkpointXDCR:171] INFO - Checkpoint on this node (this run): 0
[2015-02-17 18:17:13,982] - [checkpointXDCR:263] INFO - Checkpointing failed - may not be an error if vb_uuid changed
FAIL