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

Newly-elected primaries can commit index builds with inconsistencies due to ignoring indexing errors as secondary

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.3.4
    • Affects Version/s: None
    • Component/s: Index Maintenance
    • None
    • Fully Compatible
    • ALL
    • Hide

      After applying the patch with 'git am < bf.patch', run 'python buildscripts/resmoke.py --suites=no_passthrough jsTests/noPassthrough/repro.js'

      (This patch was taken from base c92e20479618b22355b9fb7efa935ff6db5883a9).

      From 23f0b72f7560359573b92db569676ebff5e01dce Mon Sep 17 00:00:00 2001
      From: Gregory Wlodarek <gregory.wlodarek@mongodb.com>
      Date: Thu, 2 Jan 2020 15:35:25 -0500
      Subject: [PATCH] BF-15731
      
      ---
       jstests/noPassthrough/repro.js            | 45 +++++++++++++++++++++++
       src/mongo/db/index_builds_coordinator.cpp |  6 +++
       2 files changed, 51 insertions(+)
       create mode 100644 jstests/noPassthrough/repro.js
      
      diff --git a/jstests/noPassthrough/repro.js b/jstests/noPassthrough/repro.js
      new file mode 100644
      index 0000000000..2414b30edd
      --- /dev/null
      +++ b/jstests/noPassthrough/repro.js
      @@ -0,0 +1,45 @@
      +/**
      + * @tags: [requires_replication]
      + */
      +(function() {
      +"use strict";
      +
      +const dbName = "test";
      +const collName = "geo";
      +
      +const rst = new ReplSetTest({nodes: 2});
      +rst.startSet();
      +rst.initiate();
      +
      +const db = rst.getPrimary().getDB(dbName);
      +assert.commandWorked(db.createCollection(collName));
      +assert.commandWorked(db.getCollection(collName).insert({pos: "invalid"}));
      +rst.awaitReplication();
      +
      +const failpoint = 'hangBeforeRunningIndexBuildWithoutLocks';
      +assert.commandWorked(db.adminCommand({configureFailPoint: failpoint, mode: "alwaysOn"}));
      +
      +const awaitCreateIndex = startParallelShell(() => {
      +    assert.commandFailedWithCode(
      +        db.getCollection("geo").createIndex({pos: "geoHaystack", type: 1}, {bucketSize: 1}),
      +        ErrorCodes.InterruptedDueToReplStateChange);
      +}, rst.getPrimary().port);
      +
      +checkLog.contains(rst.getPrimary(), "Hang before running index build without locks");
      +
      +jsTestLog("Making Primary step down");
      +assert.commandWorked(rst.getPrimary().adminCommand(
      +    {"replSetStepDown": 100, secondaryCatchUpPeriodSecs: 0, "force": true}));
      +
      +// New primary fails validate because we managed to built a corrupted index.
      +const validateRes =
      +    assert.commandWorked(rst.getPrimary().getDB(dbName).getCollection(collName).validate());
      +jsTestLog("Validate Response: " + tojson(validateRes));
      +assert.eq(false, validateRes.valid);
      +
      +// Old primary fasserts() when trying to commit the index build.
      +assert.commandWorked(rst.getSecondary().adminCommand({configureFailPoint: failpoint, mode: "off"}));
      +awaitCreateIndex();
      +
      +rst.stopSet();
      +}());
      diff --git a/src/mongo/db/index_builds_coordinator.cpp b/src/mongo/db/index_builds_coordinator.cpp
      index 5e52d4403c..51b319d3b9 100644
      --- a/src/mongo/db/index_builds_coordinator.cpp
      +++ b/src/mongo/db/index_builds_coordinator.cpp
      @@ -67,6 +67,7 @@ using namespace indexbuildentryhelpers;
       MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildFirstDrain);
       MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildSecondDrain);
       MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildDumpsInsertsFromBulk);
      +MONGO_FAIL_POINT_DEFINE(hangBeforeRunningIndexBuildWithoutLocks);
      
       namespace {
      
      @@ -1372,6 +1373,11 @@ void IndexBuildsCoordinator::_runIndexBuildInner(OperationContext* opCtx,
           // This Status stays unchanged unless we catch an exception in the following try-catch block.
           auto status = Status::OK();
           try {
      +        if (hangBeforeRunningIndexBuildWithoutLocks.shouldFail()) {
      +            log() << "Hang before running index build without locks";
      +            hangBeforeRunningIndexBuildWithoutLocks.pauseWhileSet();
      +        }
      +
               // Lock acquisition might throw, and we would still need to clean up the index build state,
               // so do it in the try-catch block
               AutoGetDb autoDb(opCtx, replState->dbName, MODE_IX);
      --
      2.23.0
      
      Show
      After applying the patch with 'git am < bf.patch', run 'python buildscripts/resmoke.py --suites=no_passthrough jsTests/noPassthrough/repro.js' (This patch was taken from base c92e20479618b22355b9fb7efa935ff6db5883a9). From 23f0b72f7560359573b92db569676ebff5e01dce Mon Sep 17 00:00:00 2001 From: Gregory Wlodarek <gregory.wlodarek@mongodb.com> Date: Thu, 2 Jan 2020 15:35:25 -0500 Subject: [PATCH] BF-15731 --- jstests/noPassthrough/repro.js | 45 +++++++++++++++++++++++ src/mongo/db/index_builds_coordinator.cpp | 6 +++ 2 files changed, 51 insertions(+) create mode 100644 jstests/noPassthrough/repro.js diff --git a/jstests/noPassthrough/repro.js b/jstests/noPassthrough/repro.js new file mode 100644 index 0000000000..2414b30edd --- /dev/ null +++ b/jstests/noPassthrough/repro.js @@ -0,0 +1,45 @@ +/** + * @tags: [requires_replication] + */ +(function() { + "use strict" ; + + const dbName = "test" ; + const collName = "geo" ; + + const rst = new ReplSetTest({nodes: 2}); +rst.startSet(); +rst.initiate(); + + const db = rst.getPrimary().getDB(dbName); + assert .commandWorked(db.createCollection(collName)); + assert .commandWorked(db.getCollection(collName).insert({pos: "invalid" })); +rst.awaitReplication(); + + const failpoint = 'hangBeforeRunningIndexBuildWithoutLocks' ; + assert .commandWorked(db.adminCommand({configureFailPoint: failpoint, mode: "alwaysOn" })); + + const awaitCreateIndex = startParallelShell(() => { + assert .commandFailedWithCode( + db.getCollection( "geo" ).createIndex({pos: "geoHaystack" , type: 1}, {bucketSize: 1}), + ErrorCodes.InterruptedDueToReplStateChange); +}, rst.getPrimary().port); + +checkLog.contains(rst.getPrimary(), "Hang before running index build without locks" ); + +jsTestLog( "Making Primary step down" ); + assert .commandWorked(rst.getPrimary().adminCommand( + { "replSetStepDown" : 100, secondaryCatchUpPeriodSecs: 0, "force" : true })); + + // New primary fails validate because we managed to built a corrupted index. + const validateRes = + assert .commandWorked(rst.getPrimary().getDB(dbName).getCollection(collName).validate()); +jsTestLog( "Validate Response: " + tojson(validateRes)); + assert .eq( false , validateRes.valid); + + // Old primary fasserts() when trying to commit the index build. + assert .commandWorked(rst.getSecondary().adminCommand({configureFailPoint: failpoint, mode: "off" })); +awaitCreateIndex(); + +rst.stopSet(); +}()); diff --git a/src/mongo/db/index_builds_coordinator.cpp b/src/mongo/db/index_builds_coordinator.cpp index 5e52d4403c..51b319d3b9 100644 --- a/src/mongo/db/index_builds_coordinator.cpp +++ b/src/mongo/db/index_builds_coordinator.cpp @@ -67,6 +67,7 @@ using namespace indexbuildentryhelpers; MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildFirstDrain); MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildSecondDrain); MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildDumpsInsertsFromBulk); +MONGO_FAIL_POINT_DEFINE(hangBeforeRunningIndexBuildWithoutLocks); namespace { @@ -1372,6 +1373,11 @@ void IndexBuildsCoordinator::_runIndexBuildInner(OperationContext* opCtx, // This Status stays unchanged unless we catch an exception in the following try - catch block. auto status = Status::OK(); try { + if (hangBeforeRunningIndexBuildWithoutLocks.shouldFail()) { + log() << "Hang before running index build without locks" ; + hangBeforeRunningIndexBuildWithoutLocks.pauseWhileSet(); + } + // Lock acquisition might throw , and we would still need to clean up the index build state, // so do it in the try - catch block AutoGetDb autoDb(opCtx, replState->dbName, MODE_IX); -- 2.23.0
    • Execution Team 2020-01-27, Execution Team 2020-02-10
    • 26

      Looking at the code, it looks like the issue stems from IndexBuildsCoordinator::onStepUp() as it commits index builds regardless of whether they should be aborted.

      I was able to reproduce this, but here is a timeline of events leading up to this problem:

      • Node 1 (Primary): Start a geo index build that should fail at the end due to an invalid document for this type of index in the collection.
      • Node 2 (Secondary): Start the same index build after seeing the start index build oplog entry, and finish the index build up until the final phase before the primary node. The secondary node now waits for the commit/abort oplog entry from the primary.
      • Node 1 (Primary): Step-down after finishing the index build but before aborting the index build and sending the abort oplog entry to the secondary.
      • Node 2 becomes primary, Node 1 becomes secondary.
      • Node 2 (Primary): Step-up and commit the index build. This was rather unexpected, I would expect an abort index build oplog entry here. Perhaps the onStepUp() function forgets to check the state of the index build.
      • Node 2 (Primary): Running validate on this node will fail because we committed an invalid index and validate sees that as a case of corruption:
      {
       	"valid" : false,
       	"warnings" : [ ],
       	"errors" : [
       		"exception during collection validation: Location16775: cannot extract [lng, lat] array or object from { _id: ObjectId('5e0f730ab7d4d029001cd7b7'), pos: \"invalid\" }"
       	],
       	"extraIndexEntries" : [ ],
       	"missingIndexEntries" : [ ],
       	"advice" : "A corrupt namespace has been detected. See http://dochub.mongodb.org/core/data-recovery for recovery steps.",
       	"ok" : 1,
       	"$clusterTime" : {
       		"clusterTime" : Timestamp(1578070806, 2),
       		"signature" : {
       			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
       			"keyId" : NumberLong(0)
       		}
       	},
       	"operationTime" : Timestamp(1578070806, 2)
      }
      

      * Node 1 (Secondary): fasserts() when trying to commit the index build after receiving the commit index build oplog entry from the new primary.

      [IndexBuildsCoordinatorMongod-0] Fatal assertion 51101 Location16775: Index build: 21ddcd36-e6c3-4b41-a687-12304a79ac9a; Database: test :: caused by :: index build failed on this node but we received a commitIndexBuild oplog entry from the primary with timestamp: Timestamp(1578070806, 2) :: caused by :: cannot extract [lng, lat] array or object from { _id: ObjectId('5e0f730ab7d4d029001cd7b7'), pos: "invalid" } at src/mongo/db/index_builds_coordinator.cpp 1355
      

            Assignee:
            louis.williams@mongodb.com Louis Williams
            Reporter:
            gregory.wlodarek@mongodb.com Gregory Wlodarek
            Votes:
            0 Vote for this issue
            Watchers:
            5 Start watching this issue

              Created:
              Updated:
              Resolved: