[SERVER-45933] 2 phase index build running with maxTimeMS can lead to undesirable behavior like server crash. Created: 03/Feb/20  Updated: 29/Oct/23  Resolved: 17/Apr/20

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

Type: Bug Priority: Major - P3
Reporter: Suganthi Mani Assignee: Benety Goh
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-44953 Secondaries should restart index buil... Closed
related to SERVER-45378 IndexBuildsCoordinator::_setUpIndexBu... Closed
related to SERVER-45921 Index builder invariants on this chec... Closed
related to SERVER-73164 increase maxTimeMS for index build in... Closed
is related to SERVER-37643 add createIndexes command logic to th... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4
Steps To Reproduce:

Base commit: c5cc18dd7484867d82959fc221eeb42efae94255

diff --git a/jstests/replsets/two_phase_index_build_maxtimems.js b/jstests/replsets/two_phase_index_build_maxtimems.js
new file mode 100644
index 0000000000..40382f7d54
--- /dev/null
+++ b/jstests/replsets/two_phase_index_build_maxtimems.js
@@ -0,0 +1,55 @@
+/*
+ * Test shows that 2 phase index build with maxTimeMs can cause server crash.
+ */
+load('jstests/libs/parallelTester.js');
+load("jstests/libs/curop_helpers.js");  // for waitForCurOpByFailPoint().
+load("jstests/replsets/rslib.js");
+load('jstests/noPassthrough/libs/index_build.js');
+
+(function() {
+
+"use strict";
+
+const testName = "readOpsDuringStepDown";
+const dbName = "test";
+const collName = "coll";
+
+var rst = new ReplSetTest({name: testName, nodes: [{}, {rsConfig: {priority: 0}}]});
+rst.startSet();
+rst.initiate();
+
+const primary = rst.getPrimary();
+const primaryDB = primary.getDB(dbName);
+const primaryAdmin = primary.getDB("admin");
+const primaryColl = primaryDB[collName];
+const collNss = primaryColl.getFullName();
+
+TestData.dbName = dbName;
+TestData.collName = collName;
+
+jsTestLog("Do a document write");
+assert.commandWorked(
+        primaryColl.insert({_id: 0, x: 0}, {"writeConcern": {"w": "majority"}}));
+rst.awaitReplication();
+
+// This fail point will delay 4 sec delay in index build. But, we are going to
+// create index with maxTimeMS set as 1 sec.
+jsTestLog("Make the  index builder to hang before building index");
+const hangBeforeBuildingIndexFailpointTimesEntered = assert.commandWorked(primary.adminCommand(
+    {configureFailPoint: 'hangBeforeBuildingIndex', mode: 'alwaysOn'})).count;
+
+
+const joinFindThread = startParallelShell(() => {
+    jsTestLog("Create index with maxTimeMS set");
+    assert.commandWorked(db.getSiblingDB(TestData.dbName).runCommand(
+        {createIndexes: TestData.collName, indexes: [{name: "x_1", key: {x: 1}}], maxTimeMS: 1 * 1000}));
+}, primary.port);
+
+// Wait for index build to reach the fail point.
+checkLog.contains(primary, "Bulk builder hung before building index");
+
+// Induce state transition.
+assert.commandWorked(primary.adminCommand({"replSetStepDown": 100, "force": true}));
+
+rst.stopSet();
+})();
diff --git a/src/mongo/db/index_builds_coordinator.cpp b/src/mongo/db/index_builds_coordinator.cpp
index 77c667a42d..2024267339 100644
--- a/src/mongo/db/index_builds_coordinator.cpp
+++ b/src/mongo/db/index_builds_coordinator.cpp
@@ -68,6 +68,7 @@ using namespace indexbuildentryhelpers;
 MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildFirstDrain);
 MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildSecondDrain);
 MONGO_FAIL_POINT_DEFINE(hangAfterIndexBuildDumpsInsertsFromBulk);
+MONGO_FAIL_POINT_DEFINE(hangBeforeBuildingIndex);
 
 namespace {
 
@@ -1531,6 +1532,11 @@ void IndexBuildsCoordinator::_runIndexBuildInner(OperationContext* opCtx,
         // so do it in the try-catch block
         AutoGetDb autoDb(opCtx, replState->dbName, MODE_IX);
 
+        if (MONGO_unlikely(hangBeforeBuildingIndex.shouldFail())) {
+            log() << "Bulk builder hung before building index";
+            mongo::sleepmillis(3 * 1000);
+        }
+
         // Do not use AutoGetCollection since the lock will be reacquired in various modes
         // throughout the index build. Lock by UUID to protect against concurrent collection rename.
         boost::optional<Lock::CollectionLock> collLock;

Sprint: Execution Team 2020-04-06, Execution Team 2020-04-20
Participants:

 Description   

Currently, When we run 2 phase index build with maxTimeMS, it can lead to below undesirable behaviors.
Server crash due to fassert:
When primary gets createIndex cmd with maxTimeMS set, we start building index with maxTimeMS/deadline set on that indexBuildCoordinator thread opCtx.

Now, assume, index builder thread tries to acquire a lock whose opCtx deadline got expired. This would result in throwing with ErrorCodes::MaxTimeMSExpired. On error, index builder would try to clean up the index build. Now, assume, the primary stepped down. This means, the clean up code path for secondary will be executed and hitting this fassert. Because, on secondaries it's illegal for index builder thread to throw some error unless it's asked to get aborted by abortIndexBuild oplog entry (exceptional is shutdown).

Note: repro patch attached for this scenario.

Server crash due to invariant:
There is also ways it can lead to issue like SERVER-45921. Think of a case, where the createIndex parent thread opCtx got interrupted due to ErrorCodes::MaxTimeMSExpired. This makes the parent thread to signal index builder thread to abort. Assume, step down happened. This means, we get into clean up code path for secondary for ErrorCodes::IndexBuildAborted which will tear down the index build. As a result, new fail-over (previous secondary) node will take the responsibility of committing the index build that got aborted on previous primary. So, when the old primary get the commitIndexBuildOplog entry, we would try to restart the index build and lead to an invariant failure.



 Comments   
Comment by Githook User [ 17/Apr/20 ]

Author:

{'name': 'Benety Goh', 'email': 'benety@mongodb.com', 'username': 'benety'}

Message: SERVER-45933 index builds support maxTimeMS through createIndexes interruptions

(cherry picked from commit f889e85da61e90586d032e8b706bf9506919f253)
Branch: v4.4
https://github.com/mongodb/mongo/commit/6d4ed7a8b959eed6a8b3d899fef971f80e1ecc07

Comment by Githook User [ 16/Apr/20 ]

Author:

{'name': 'Benety Goh', 'email': 'benety@mongodb.com', 'username': 'benety'}

Message: SERVER-45933 index builds support maxTimeMS through createIndexes interruptions
Branch: master
https://github.com/mongodb/mongo/commit/f889e85da61e90586d032e8b706bf9506919f253

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