diff options
| -rw-r--r-- | jstests/noPassthrough/profile_interrupted_op.js | 75 | ||||
| -rw-r--r-- | src/mongo/db/introspect.cpp | 20 |
2 files changed, 92 insertions, 3 deletions
diff --git a/jstests/noPassthrough/profile_interrupted_op.js b/jstests/noPassthrough/profile_interrupted_op.js new file mode 100644 index 00000000000..4eba5fa7e10 --- /dev/null +++ b/jstests/noPassthrough/profile_interrupted_op.js @@ -0,0 +1,75 @@ +// Test what happens when the profiler (introspect.cpp) wants to log an operation, but the +// 'system.profiler' collection does not yet exist and is not safe to create, because the operation +// context is an interrupted state (SERVER-38481). +// +// This test restarts the server and requires that data persists across restarts. +// @tags: [requires_persistence] + +(function() { + "use strict"; + + load("jstests/libs/check_log.js"); // For checkLog. + + // + // Start mongo with profiling disabled, create an empty database, and populate it with a + // collection that has one document. + // + let standalone = MongoRunner.runMongod({profile: "0"}); + + let db = standalone.getDB("profile_interrupted_op"); + assert.commandWorked(db.dropDatabase()); + + let coll = db.getCollection("test"); + assert.commandWorked(coll.insert({a: 1})); + + // + // Stop the mongod and then restart it, this time with profiling enabled. Note that enabling + // profiling on a running database would create the 'system.profile' collection, which we don't + // yet want created for this test. + // + MongoRunner.stopMongod(standalone); + standalone = MongoRunner.runMongod( + {restart: true, cleanData: false, dbpath: standalone.dbpath, profile: "2"}); + + // + // Execute a query that will get interrupted for exceeding its 'maxTimeMS' value. The profiler + // will attempt to create the 'system.profile' collection while the operation context is already + // marked as interrupted. + // + db = standalone.getDB("profile_interrupted_op"); + coll = db.getCollection("test"); + const err = assert.throws(function() { + coll.find({ + $where: function() { + sleep(3600); + return true; + } + }) + .maxTimeMS(1000) + .count(); + }); + assert.contains(err.code, + [ErrorCodes.MaxTimeMSExpired, ErrorCodes.Interrupted, ErrorCodes.InternalError], + err); + + // + // Profiling is not necessary for the rest of the test. We turn it off to make sure it doesn't + // interfere with any remaining commands. + // + db.setProfilingLevel(0); + + // + // The mongod should print out a warning to indicate the potential need for a manually created + // 'system.profile' collection. + // + checkLog.contains(standalone, "Manually create profile collection"); + + // + // The mongod should not create the 'system.profile' collection automatically. + // + const res = db.runCommand({listCollections: 1, filter: {name: "system.profile"}}); + assert.commandWorked(res); + assert.eq(res.cursor.firstBatch, [], res); + + MongoRunner.stopMongod(standalone); +})(); diff --git a/src/mongo/db/introspect.cpp b/src/mongo/db/introspect.cpp index 8bda2543426..fe8405db343 100644 --- a/src/mongo/db/introspect.cpp +++ b/src/mongo/db/introspect.cpp @@ -117,6 +117,10 @@ void profile(OperationContext* opCtx, NetworkOp op) { const string dbName(nsToDatabase(CurOp::get(opCtx)->getNS())); + // True if we need to acquire an X lock on the database in order to create the system.profile + // collection. + bool acquireDbXLock = false; + try { // Even if the operation we are profiling was interrupted, we still want to output the // profiler entry. This lock guard will prevent lock acquisitions from throwing exceptions @@ -127,10 +131,12 @@ void profile(OperationContext* opCtx, NetworkOp op) { noInterrupt.emplace(opCtx->lockState()); } - bool acquireDbXLock = false; while (true) { std::unique_ptr<AutoGetDb> autoGetDb; if (acquireDbXLock) { + // We should not attempt to acquire an X lock while in "noInterrupt" scope. + noInterrupt.reset(); + autoGetDb.reset(new AutoGetDb(opCtx, dbName, MODE_X)); if (autoGetDb->getDb()) { createProfileCollection(opCtx, autoGetDb->getDb()).transitional_ignore(); @@ -170,8 +176,16 @@ void profile(OperationContext* opCtx, NetworkOp op) { } } } catch (const AssertionException& assertionEx) { - warning() << "Caught Assertion while trying to profile " << networkOpToString(op) - << " against " << CurOp::get(opCtx)->getNS() << ": " << redact(assertionEx); + if (acquireDbXLock && assertionEx.isA<ErrorCategory::Interruption>()) { + warning() + << "Interrupted while attempting to create profile collection in database " + << dbName << " to profile operation " << networkOpToString(op) << " against " + << CurOp::get(opCtx)->getNS() + << ". Manually create profile collection to ensure future operations are logged."; + } else { + warning() << "Caught Assertion while trying to profile " << networkOpToString(op) + << " against " << CurOp::get(opCtx)->getNS() << ": " << redact(assertionEx); + } } } |