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

access_collection_in_transaction_after_catalog_changes.js should expect the NoMatchingDocument error code when an index build is aborted

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 5.0.0-rc0, 5.1.0-rc0, 4.4.20
    • Affects Version/s: None
    • Component/s: None
    • None
    • Fully Compatible
    • ALL
    • v5.0, v4.4
    • Execution Team 2021-05-31
    • 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.

            Assignee:
            gregory.wlodarek@mongodb.com Gregory Wlodarek
            Reporter:
            gregory.wlodarek@mongodb.com Gregory Wlodarek
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: