GoXDCR: After online upgrade, CAS values do not match for expired -->deleted keys

Build
------
4.0.0-1869

Testcase
--------
./testrunner -i INI_FILE.ini -p upgrade_version=4.0.0-1869,initial_vbuckets=1024 -t "xdcr.upgradeXDCR.UpgradeTests.online_cluster_upgrade,initial_version=2.5.0-1059-rel,bucket_topology=default:1>2;standard_bucket_1:1<2;sasl_bucket_1:1><2,expires=500,post-upgrade-actions=src-rebalancein;dest-rebalanceout"

test_5 in http://qa.hq.northscale.net/view/3.0%20By%20COMPONENT/job/cen006-p1-xxdcr-vset05-02-goxdcr-backward-compatibility-and-upgrade

Steps

---

1. Install 2.5.0 on C1 [.11,.16] and C2 [.19,.20]. Install 4.0.0-1869 on extra node .21.
2. Setup xdcr:
C1.default --> C2.default
C1.sasl <--> C2.sasl
C1.standard <-- C2.standard
3. Load 1000 keys (no expiration) into C1.default, C1.sasl, C2.sasl and C2.standard
4. Rebalance in .21 to C1.
5. Rebalance out old nodes .11 and .16 from C1. Leaving C1 a pure sherlock cluster.
6. Update 300 keys on C1.default and C1.sasl with expiration=500secs.
7. Install 4.0.0-1869 on .11 and .16 and rebalance into C1. Rebalance out .21.
8. Update 300 keys on C1.default and C1.sasl with expiration=500secs again.
Also delete 300 keys on C1.default and C1.sasl. These are C1-keys from step 3.
9. Reinstall 4.0.0 on .21 to make sure node is clean
10. Rebalance in .21 to C2. Rebalance out old nodes.
11. Install 4.0.0-1869 on .19 and .20 and rebalance into C2. Rebalance out .21..
12. Update 300 keys on C2.standard and C2.sasl with expiration=500secs.
Also delete 300 keys on C2.standard and C2.sasl. These are C2-keys loaded in step 3.
13. Run expiry pager on all nodes.

The upgrade itself was successful. The deletes and updates in step 12 and 13 got replicated.

However, replication after step 6 or step 8 has resulted in the CAS mismatch we see below. Seen for all 300 keys updated on C1.sasl.

[2015-04-16 14:57:20,482] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne287 =====
[2015-04-16 14:57:20,483] - [task:1398] ERROR - cas mismatch: Source cas:1429218582664708097, Destination cas:1429220109321874776, Error Count:1
[2015-04-16 14:57:20,484] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582664708097, 'flags': 0, 'expiration': 1429221417}

[2015-04-16 14:57:20,485] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220109321874776, 'flags': 0, 'expiration': 1429220509}

[2015-04-16 14:57:20,487] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne183 =====
[2015-04-16 14:57:20,487] - [task:1398] ERROR - cas mismatch: Source cas:1429218582643081217, Destination cas:1429220089684562520, Error Count:2
[2015-04-16 14:57:20,488] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582643081217, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,489] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220089684562520, 'flags': 0, 'expiration': 1429220673}

[2015-04-16 14:57:20,492] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne2 =====
[2015-04-16 14:57:20,492] - [task:1398] ERROR - cas mismatch: Source cas:1429218582643146753, Destination cas:1429219339965217639, Error Count:3
[2015-04-16 14:57:20,493] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582643146753, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,493] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219339965217639, 'flags': 0, 'expiration': 1429220682}

[2015-04-16 14:57:20,559] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne141 =====
[2015-04-16 14:57:20,560] - [task:1398] ERROR - cas mismatch: Source cas:1429218582663004161, Destination cas:1429219401947728449, Error Count:4
[2015-04-16 14:57:20,560] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582663004161, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,561] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219401947728449, 'flags': 0, 'expiration': 1429220517}

[2015-04-16 14:57:20,564] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne80 =====
[2015-04-16 14:57:20,565] - [task:1398] ERROR - cas mismatch: Source cas:1429218582643277825, Destination cas:1429220085358453372, Error Count:5
[2015-04-16 14:57:20,565] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582643277825, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,566] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220085358453372, 'flags': 0, 'expiration': 1429220671}

[2015-04-16 14:57:20,577] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne224 =====
[2015-04-16 14:57:20,578] - [task:1398] ERROR - cas mismatch: Source cas:1429218582663069697, Destination cas:1429219329655899404, Error Count:6
[2015-04-16 14:57:20,578] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582663069697, 'flags': 0, 'expiration': 1429221419}

[2015-04-16 14:57:20,579] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219329655899404, 'flags': 0, 'expiration': 1429220513}

[2015-04-16 14:57:20,581] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne213 =====
[2015-04-16 14:57:20,581] - [task:1398] ERROR - cas mismatch: Source cas:1429218582641508353, Destination cas:1429219975203030654, Error Count:7
[2015-04-16 14:57:20,582] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582641508353, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,583] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219975203030654, 'flags': 0, 'expiration': 1429220458}

[2015-04-16 14:57:20,585] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne245 =====
[2015-04-16 14:57:20,585] - [task:1398] ERROR - cas mismatch: Source cas:1429218582672244737, Destination cas:1429220062283888604, Error Count:8
[2015-04-16 14:57:20,586] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582672244737, 'flags': 0, 'expiration': 1429221417}

[2015-04-16 14:57:20,586] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220062283888604, 'flags': 0, 'expiration': 1429220484}

[2015-04-16 14:57:20,588] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne108 =====
[2015-04-16 14:57:20,589] - [task:1398] ERROR - cas mismatch: Source cas:1429218582643539969, Destination cas:1429220060162488672, Error Count:9
[2015-04-16 14:57:20,589] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582643539969, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,590] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220060162488672, 'flags': 0, 'expiration': 1429220484}

[2015-04-16 14:57:20,600] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne169 =====
[2015-04-16 14:57:20,601] - [task:1398] ERROR - cas mismatch: Source cas:1429218582672310273, Destination cas:1429219456223926067, Error Count:10
[2015-04-16 14:57:20,602] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582672310273, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,602] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219456223926067, 'flags': 0, 'expiration': 1429220519}

[2015-04-16 14:57:20,605] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne42 =====
[2015-04-16 14:57:20,605] - [task:1398] ERROR - cas mismatch: Source cas:1429218582663397377, Destination cas:1429219445955012744, Error Count:11
[2015-04-16 14:57:20,606] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582663397377, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,606] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219445955012744, 'flags': 0, 'expiration': 1429220518}

[2015-04-16 14:57:20,645] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne23 =====
[2015-04-16 14:57:20,646] - [task:1398] ERROR - cas mismatch: Source cas:1429218582672375809, Destination cas:1429220051145838164, Error Count:12
[2015-04-16 14:57:20,646] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582672375809, 'flags': 0, 'expiration': 1429221417}

[2015-04-16 14:57:20,647] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220051145838164, 'flags': 0, 'expiration': 1429220478}

[2015-04-16 14:57:20,664] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne298 =====
[2015-04-16 14:57:20,665] - [task:1398] ERROR - cas mismatch: Source cas:1429218582641246209, Destination cas:1429219399977851035, Error Count:13
[2015-04-16 14:57:20,665] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582641246209, 'flags': 0, 'expiration': 1429221418}

[2015-04-16 14:57:20,666] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429219399977851035, 'flags': 0, 'expiration': 1429220690}

[2015-04-16 14:57:20,735] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne176 =====
[2015-04-16 14:57:20,735] - [task:1398] ERROR - cas mismatch: Source cas:1429218582663593985, Destination cas:1429220052292488610, Error Count:14
[2015-04-16 14:57:20,736] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582663593985, 'flags': 0, 'expiration': 1429221417}

[2015-04-16 14:57:20,736] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220052292488610, 'flags': 0, 'expiration': 1429220479}

[2015-04-16 14:57:20,738] - [task:1397] ERROR - ===== Verifying rev_ids failed for key: loadOne75 =====
[2015-04-16 14:57:20,739] - [task:1398] ERROR - cas mismatch: Source cas:1429218582667132929, Destination cas:1429220057863442320, Error Count:15
[2015-04-16 14:57:20,739] - [task:1399] ERROR - Source meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429218582667132929, 'flags': 0, 'expiration': 1429221417}

[2015-04-16 14:57:20,740] - [task:1400] ERROR - Dest meta data:

{'deleted': 1, 'seqno': 4, 'cas': 1429220057863442320, 'flags': 0, 'expiration': 1429220482}

Link to logs attached. Feel free to assign to ep-engine team.