Loading...

Type: Bug
Resolution: Fixed
Priority: Major - P3
Fix Version/s: 5.0.0-rc0, 5.1.0-rc0, 4.4.20
Affects Version/s: None
Component/s: None
Labels:
None

Backwards Compatibility:
Fully Compatible
Operating System:
ALL
Backport Requested:

v5.0, v4.4
Sprint:
Execution Team 2021-05-31
Linked BF Score:
18

The index builder thread was running the voteCommitIndexBuild when the collection was dropped, causing the index build to be aborted.

[j0:prim] | 2021-03-22T05:32:52.262+00:00 I  INDEX    20438   [conn2606] "Index build: registering","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","collectionUUID":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"indexes":1,"firstIndex":{"name":"x_1"}}
[j0:prim] | 2021-03-22T05:32:52.341+00:00 I  INDEX    20384   [IndexBuildsCoordinatorMongod-3] "Index build: starting","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"collectionUUID":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","properties":{"v":2,"key":{"x":1},"name":"x_1"},"method":"Hybrid","maxTemporaryMemoryUsageMB":200}
[j0:prim] | 2021-03-22T05:32:52.396+00:00 I  INDEX    20346   [IndexBuildsCoordinatorMongod-3] "Index build: initialized","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"collectionUUID":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","initializationTimestamp":{"$timestamp":{"t":1616391172,"i":32}}}
[j0:prim] | 2021-03-22T05:32:52.405+00:00 I  STORAGE  4847600 [IndexBuildsCoordinatorMongod-3] "Index build: waiting for last optime before interceptors to be majority committed","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"collectionUUID":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"deadline":{"$date":"2021-03-22T05:33:02.403Z"},"timeoutMillis":10000,"lastOpTime":{"ts":{"$timestamp":{"t":1616391172,"i":36}},"t":1}}
[j0:prim] | 2021-03-22T05:32:52.409+00:00 I  INDEX    20440   [conn2606] "Index build: waiting for index build to complete","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"deadline":{"$date":{"$numberLong":"9223372036854775807"}}}
[j0:prim] | 2021-03-22T05:32:52.547+00:00 I  INDEX    20391   [IndexBuildsCoordinatorMongod-3] "Index build: collection scan done","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"collectionUUID":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","totalRecords":3,"readSource":"kMajorityCommitted","durationMillis":0}
[j0:prim] | 2021-03-22T05:32:52.557+00:00 I  INDEX    20685   [IndexBuildsCoordinatorMongod-3] "Index build: inserted keys from external sorter into index","attr":{"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","index":"x_1","keysInserted":3,"durationMillis":0}
[j0:prim] | 2021-03-22T05:32:52.671+00:00 I  INDEX    20689   [IndexBuildsCoordinatorMongod-3] "Index build: drained side writes","attr":{"index":"x_1","collectionUUID":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","numApplied":3,"totalInserted":2,"totalDeleted":1,"durationMillis":11}
[j0:prim] | 2021-03-22T05:32:52.688+00:00 I  COMMAND  51803   [conn757] "Slow query","attr":{"type":"command","ns":"config.system.indexBuilds","command":{"voteCommitIndexBuild":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"},"hostAndPort":"localhost:20001","writeConcern":{"w":"majority"},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1616391172,"i":43}},"signature":{"hash":{"$binary":{"base64":"beyCKo+9ofpUqhygO466WT8MBIk=","subType":"0"}},"keyId":6942345262778024000}},"$db":"admin"},"numYields":0,"reslen":163,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":3}},"Global":{"acquireCount":{"r":2,"w":1}},"Database":{"acquireCount":{"r":2,"w":1}},"Collection":{"acquireCount":{"r":2,"w":1}},"Mutex":{"acquireCount":{"r":5}}},"flowControl":{"acquireCount":1,"timeAcquiringMicros":20},"writeConcern":{"w":"majority","wtimeout":0,"provenance":"clientSupplied"},"storage":{},"remote":"127.0.0.1:53174","protocol":"op_msg","durationMillis":171}
[j0:prim] | 2021-03-22T05:32:52.695+00:00 I  STORAGE  23879   [conn2608] "About to abort all index builders","attr":{"namespace":"access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll","uuid":{"uuid":{"$uuid":"5a334853-b30f-49d8-864e-6bc841e78a90"}},"reason":"Collection access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll(5a334853-b30f-49d8-864e-6bc841e78a90) is being dropped"}
[j0:prim] | 2021-03-22T05:32:52.696+00:00 I  STORAGE  4656010 [conn2608] "Attempting to abort index build","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}}}
[j0:prim] | 2021-03-22T05:32:52.696+00:00 I  STORAGE  4656003 [conn2608] "Aborting index build","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"error":"Collection access_collection_in_transaction_after_catalog_changes_ddl_db.ddl_coll(5a334853-b30f-49d8-864e-6bc841e78a90) is being dropped"}
[j0:prim] | 2021-03-22T05:32:52.705+00:00 I  STORAGE  465611  [conn2608] "Cleaned up index build after abort. ","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}}}
[j0:prim] | 2021-03-22T05:32:53.056+00:00 I  STORAGE  20655   [conn2608] "Index build: joined after abort","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"waitResult":{"code":0,"codeName":"OK"},"status":{"code":47,"codeName":"NoMatchingDocument","errmsg":"failed to get commit quorum before committing index build: 27843eda-2d02-4e1d-9292-983dcd05e571 :: caused by :: No matching IndexBuildEntry found with indexBuildUUID: 27843eda-2d02-4e1d-9292-983dcd05e571"}}
[j0:prim] | 2021-03-22T05:32:53.077+00:00 I  INDEX    20449   [conn2606] "Index build: failed","attr":{"buildUUID":{"uuid":{"$uuid":"27843eda-2d02-4e1d-9292-983dcd05e571"}},"error":{"code":47,"codeName":"NoMatchingDocument","errmsg":"failed to get commit quorum before committing index build: 27843eda-2d02-4e1d-9292-983dcd05e571 :: caused by :: No matching IndexBuildEntry found with indexBuildUUID: 27843eda-2d02-4e1d-9292-983dcd05e571"}}

The index build did get aborted cleanly but returned NoMatchingDocument instead of IndexBuildAborted. This is because we tried to read the index build entry from config.system.indexBuilds while being aborted, which removed the entry.

Details

Description

Attachments

Activity

People

Dates