SERVER-38481 No strong locks in profiling while uninterruptible

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);
+        }
     }
 }