[SERVER-48772] Dropping multiple indexes incorrectly timestamps writes Created: 12/Jun/20  Updated: 29/Oct/23  Resolved: 18/Jun/20

Status: Closed
Project: Core Server
Component/s: Storage
Affects Version/s: None
Fix Version/s: 4.4.0-rc11, 4.7.0

Type: Bug Priority: Major - P3
Reporter: Daniel Gottlieb (Inactive) Assignee: Gregory Wlodarek
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
related to SERVER-48771 Enforce constraints on "multi-timesta... Closed
is related to SERVER-34777 multi-index drops are given the wrong... Closed
is related to WT-6388 Fix-up out-of-order updates in the hi... Closed
is related to WT-6409 Fix failure due to assertion during r... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4
Sprint: Execution Team 2020-06-29
Participants:

 Description   

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.



 Comments   
Comment by Githook User [ 18/Jun/20 ]

Author:

{'name': 'Gregory Wlodarek', 'email': 'gregory.wlodarek@mongodb.com', 'username': 'GWlodarek'}

Message: SERVER-48772 Correctly timestamp writes when dropping multiple indexes

(cherry picked from commit 9397a9e59b22909a6bf00050bb9653117544aea1)
Branch: v4.4
https://github.com/mongodb/mongo/commit/c7108af024e67563eb32a312eac7fb5d5bd9009f

Comment by Githook User [ 18/Jun/20 ]

Author:

{'name': 'Gregory Wlodarek', 'email': 'gregory.wlodarek@mongodb.com', 'username': 'GWlodarek'}

Message: SERVER-48772 Correctly timestamp writes when dropping multiple indexes
Branch: master
https://github.com/mongodb/mongo/commit/9397a9e59b22909a6bf00050bb9653117544aea1

Generated at Thu Feb 08 05:18:02 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.