Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-48772

Dropping multiple indexes incorrectly timestamps writes

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.4.0-rc11, 4.7.0
    • Affects Version/s: None
    • Component/s: Storage
    • None
    • Fully Compatible
    • ALL
    • v4.4
    • Execution Team 2020-06-29

      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.

            Assignee:
            gregory.wlodarek@mongodb.com Gregory Wlodarek
            Reporter:
            daniel.gottlieb@mongodb.com Daniel Gottlieb (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: