|
The following sequence was discovered. I believe this is a 4.4 specific regression.
[conn48] CMD: dropIndexes{"namespace":"test.drop_index","indexes":"[ \"c_1\", \"d_1\" ]"}
|
[conn48] WT12. Beginning transaction
|
[conn48] recording new metadata{"obj":{"md":{"ns":"test.drop_index","options":{"uuid":{"$uuid":"895bfb08-57a0-4501-a6e3-2fe905b02740"}},"indexes":[{"spec":{"v":2,"key":{"_id":1},"name":"_id_"},"ready":true,"multikey":false,"multikeyPaths":{"_id":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false},{"spec":{"v":2,"key":{"d":1.0},"name":"d_1"},"ready":true,"multikey":false,"multikeyPaths":{"d":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false},{"spec":{"v":2,"key":{"e":1.0},"name":"e_1"},"ready":true,"multikey":false,"multikeyPaths":{"e":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false},{"spec":{"v":2,"key":{"a":1.0},"name":"a_1"},"ready":true,"multikey":false,"multikeyPaths":{"a":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false}],"prefix":-1},"idxIdent":{"_id_":"index-34-1060380013860550997","d_1":"index-41-1060380013860550997","e_1":"index-43-1060380013860550997","a_1":"index-45-1060380013860550997"},"ns":"test.drop_index","ident":"collection-33-1060380013860550997"}}
|
[conn48] WT set timestamp of future write operations to {"$timestamp":{"t":1591982501,"i":14}}
|
[conn48] WT set timestamp of future write operations to {"$timestamp":{"t":1591982501,"i":14}}
|
[conn48] recording new metadata{"obj":{"md":{"ns":"test.drop_index","options":{"uuid":{"$uuid":"895bfb08-57a0-4501-a6e3-2fe905b02740"}},"indexes":[{"spec":{"v":2,"key":{"_id":1},"name":"_id_"},"ready":true,"multikey":false,"multikeyPaths":{"_id":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false},{"spec":{"v":2,"key":{"e":1.0},"name":"e_1"},"ready":true,"multikey":false,"multikeyPaths":{"e":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false},{"spec":{"v":2,"key":{"a":1.0},"name":"a_1"},"ready":true,"multikey":false,"multikeyPaths":{"a":{"$binary":{"base64":"AA==","subType":"0"}}},"head":0,"prefix":-1,"backgroundSecondary":false}],"prefix":-1},"idxIdent":{"_id_":"index-34-1060380013860550997","e_1":"index-43-1060380013860550997","a_1":"index-45-1060380013860550997"},"ns":"test.drop_index","ident":"collection-33-1060380013860550997"}}
|
[conn48] WT set timestamp of future write operations to {"$timestamp":{"t":1591982501,"i":15}}
|
[conn48] WT set timestamp of future write operations to {"$timestamp":{"t":1591982501,"i":15}}
|
[conn48] WT123. Last: Timestamp(1591982501, 15) Commit: Timestamp(0, 0)
|
I suspect this would break rollback and I'm surprised we haven't seen a failure like that come through. The rollback fuzzer has caught them before.
In this case, removing index "C" happens first and gets timestamp(..., 15), then removing index "D" happens second, but gets the earlier timestamp(..., 14).
The oplog entries:
{ "op" : "c", "ns" : "test.$cmd", "ui" : UUID("895bfb08-57a0-4501-a6e3-2fe905b02740"), "o" : { "dropIndexes" : "drop_index", "index" : "d_1" }, "o2" : { "v" : 2, "key" : { "d" : 1 }, "name" : "d_1" }, "ts" : Timestamp(1591982501, 15), "t" : NumberLong(1), "wall" : ISODate("2020-06-12T17:21:41.141Z"), "v" : NumberLong(2) }
|
{ "op" : "c", "ns" : "test.$cmd", "ui" : UUID("895bfb08-57a0-4501-a6e3-2fe905b02740"), "o" : { "dropIndexes" : "drop_index", "index" : "c_1" }, "o2" : { "v" : 2, "key" : { "c" : 1 }, "name" : "c_1" }, "ts" : Timestamp(1591982501, 14), "t" : NumberLong(1), "wall" : ISODate("2020-06-12T17:21:41.141Z"), "v" : NumberLong(2) }
|
Rolling back to 14 should give index C and not D, but given the update chain would result in neither C nor D existing.
|