SERVER-53197 Don't log awaitable hello/ismaster as slow query

5 files changed, 36 insertions, 28 deletions

diff --git a/jstests/noPassthrough/awaitable_ismaster.js b/jstests/noPassthrough/awaitable_ismaster.js
index c0d25590771..5a9fb358964 100644
--- a/jstests/noPassthrough/awaitable_ismaster.js
+++ b/jstests/noPassthrough/awaitable_ismaster.js
@@ -4,6 +4,7 @@
  */
 (function() {
 "use strict";
+load("jstests/libs/fail_point_util.js");
 load("jstests/libs/parallel_shell_helpers.js");
 
 function runTest(db) {
@@ -22,16 +23,25 @@ function runTest(db) {
     assert.commandWorked(
         db.runCommand({isMaster: 1, topologyVersion: topologyVersionField, maxAwaitTimeMS: 0}));
 
-    // Ensure isMaster waits for at least maxAwaitTimeMS before returning.
+    // Ensure the command waits for at least maxAwaitTimeMS before returning, and doesn't appear in
+    // slow query log even if it takes many seconds.
+    assert.commandWorked(db.adminCommand({clearLog: 'global'}));
     let now = new Date();
+    jsTestLog(`Running slow isMaster`);
     assert.commandWorked(
-        db.runCommand({isMaster: 1, topologyVersion: topologyVersionField, maxAwaitTimeMS: 2000}));
+        db.runCommand({isMaster: 1, topologyVersion: topologyVersionField, maxAwaitTimeMS: 20000}));
     let isMasterDuration = new Date() - now;
     // Allow for some clock imprecision between the server and the jstest.
     assert.gte(
         isMasterDuration,
-        1000,
-        `isMaster should have taken at least 1000ms, but completed in ${isMasterDuration}ms`);
+        10000,
+        `isMaster should have taken at least 10000ms, but completed in ${isMasterDuration}ms`);
+
+    assert(!checkLog.checkContainsOnceJson(db.getMongo(), 51803, {
+        'command': function(obj) {
+            return obj.hasOwnProperty('isMaster');
+        }
+    }));
 
     // Check that when a different processId is given, the server responds immediately.
     now = new Date();
@@ -148,18 +158,25 @@ function runTest(db) {
                                  [31373, 51759]);
 }
 
-const conn = MongoRunner.runMongod({});
+// Set command log verbosity to 0 to avoid logging *all* commands in the "slow query" log.
+const conn = MongoRunner.runMongod({setParameter: {logComponentVerbosity: tojson({command: 0})}});
 assert.neq(null, conn, "mongod was unable to start up");
 runTest(conn.getDB("admin"));
 MongoRunner.stopMongod(conn);
 
-const replTest = new ReplSetTest({nodes: 1});
+const replTest = new ReplSetTest(
+    {nodes: 1, nodeOptions: {setParameter: {logComponentVerbosity: tojson({command: 0})}}});
 replTest.startSet();
 replTest.initiate();
 runTest(replTest.getPrimary().getDB("admin"));
 replTest.stopSet();
 
-const st = new ShardingTest({mongos: 1, shards: [{nodes: 1}], config: 1});
+const st = new ShardingTest({
+    mongos: 1,
+    shards: [{nodes: 1}],
+    config: 1,
+    other: {mongosOptions: {setParameter: {logComponentVerbosity: tojson({command: 0})}}}
+});
 runTest(st.s.getDB("admin"));
 st.stop();
 })();
diff --git a/src/mongo/db/repl/replication_info.cpp b/src/mongo/db/repl/replication_info.cpp
index 3602c6cf9d5..0248c4f5b6c 100644
--- a/src/mongo/db/repl/replication_info.cpp
+++ b/src/mongo/db/repl/replication_info.cpp
@@ -40,6 +40,7 @@
 #include "mongo/db/auth/sasl_mechanism_registry.h"
 #include "mongo/db/client.h"
 #include "mongo/db/commands/server_status.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/db_raii.h"
 #include "mongo/db/dbhelpers.h"
 #include "mongo/db/exec/working_set_common.h"
@@ -452,8 +453,10 @@ public:
         // present if and only if topologyVersion is present in the request.
         auto topologyVersionElement = cmdObj["topologyVersion"];
         auto maxAwaitTimeMSField = cmdObj["maxAwaitTimeMS"];
+        auto curOp = CurOp::get(opCtx);
         boost::optional<TopologyVersion> clientTopologyVersion;
         boost::optional<long long> maxAwaitTimeMS;
+        boost::optional<ScopeGuard<std::function<void()>>> timerGuard;
         if (topologyVersionElement && maxAwaitTimeMSField) {
             clientTopologyVersion = TopologyVersion::parse(IDLParserErrorContext("TopologyVersion"),
                                                            topologyVersionElement.Obj());
@@ -472,8 +475,8 @@ public:
 
             LOGV2_DEBUG(23904, 3, "Using maxAwaitTimeMS for awaitable isMaster protocol.");
 
-            // Awaitable isMaster commands have high latency by design.
-            opCtx->setShouldIncrementLatencyStats(false);
+            curOp->pauseTimer();
+            timerGuard.emplace([curOp]() { curOp->resumeTimer(); });
         } else {
             uassert(31368,
                     (topologyVersionElement
@@ -486,6 +489,8 @@ public:
         auto currentTopologyVersion = appendReplicationInfo(
             opCtx, result, 0, useLegacyResponseFields(), clientTopologyVersion, maxAwaitTimeMS);
 
+        timerGuard.reset();  // Resume curOp timer.
+
         if (serverGlobalParams.clusterRole == ClusterRole::ConfigServer) {
             const int configServerModeNumber = 2;
             result.append("configsvr", configServerModeNumber);
diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp
index 6e02dc9af25..31f0d3acbe9 100644
--- a/src/mongo/db/service_entry_point_common.cpp
+++ b/src/mongo/db/service_entry_point_common.cpp
@@ -1717,13 +1717,6 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx,
     DbResponse dbresponse;
     if (op == dbMsg || (op == dbQuery && isCommand)) {
         dbresponse = receivedCommands(opCtx, m, behaviors);
-        // The hello/isMaster commands should take kMaxAwaitTimeMs at most, log if it takes twice
-        // that.
-        if (auto command = currentOp.getCommand();
-            command && (command->getName() == "hello" || command->getName() == "isMaster")) {
-            slowMsOverride =
-                2 * durationCount<Milliseconds>(SingleServerIsMasterMonitor::kMaxAwaitTime);
-        }
     } else if (op == dbQuery) {
         invariant(!isCommand);
         opCtx->markKillOnClientDisconnect();
diff --git a/src/mongo/s/commands/cluster_is_master_cmd.cpp b/src/mongo/s/commands/cluster_is_master_cmd.cpp
index 8f399ca650e..0401d196be5 100644
--- a/src/mongo/s/commands/cluster_is_master_cmd.cpp
+++ b/src/mongo/s/commands/cluster_is_master_cmd.cpp
@@ -35,6 +35,7 @@
 #include "mongo/db/auth/sasl_mechanism_registry.h"
 #include "mongo/db/client.h"
 #include "mongo/db/commands.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/logical_session_id.h"
 #include "mongo/db/operation_context.h"
 #include "mongo/db/ops/write_ops.h"
@@ -139,6 +140,7 @@ public:
         // present if and only if topologyVersion is present in the request.
         auto topologyVersionElement = cmdObj["topologyVersion"];
         auto maxAwaitTimeMSField = cmdObj["maxAwaitTimeMS"];
+        auto curOp = CurOp::get(opCtx);
         boost::optional<TopologyVersion> clientTopologyVersion;
         if (topologyVersionElement && maxAwaitTimeMSField) {
             clientTopologyVersion = TopologyVersion::parse(IDLParserErrorContext("TopologyVersion"),
@@ -153,8 +155,8 @@ public:
 
             LOGV2_DEBUG(23871, 3, "Using maxAwaitTimeMS for awaitable isMaster protocol.");
 
-            // Awaitable isMaster commands have high latency by design. Ignore them.
-            opCtx->setShouldIncrementLatencyStats(false);
+            curOp->pauseTimer();
+            ON_BLOCK_EXIT([curOp]() { curOp->resumeTimer(); });
 
             if (clientTopologyVersion->getProcessId() == mongosTopologyVersion.getProcessId()) {
                 uassert(51761,
diff --git a/src/mongo/s/service_entry_point_mongos.cpp b/src/mongo/s/service_entry_point_mongos.cpp
index 8d17c402840..1ae4667c4a3 100644
--- a/src/mongo/s/service_entry_point_mongos.cpp
+++ b/src/mongo/s/service_entry_point_mongos.cpp
@@ -95,18 +95,9 @@ DbResponse ServiceEntryPointMongos::handleRequest(OperationContext* opCtx, const
     if (op == dbMsg || (op == dbQuery && NamespaceString(dbm.getns()).isCommand())) {
         auto dbResponse = Strategy::clientCommand(opCtx, message);
 
-        // The hello/isMaster commands should take kMaxAwaitTimeMs at most, log if it takes twice
-        // that.
-        boost::optional<long long> slowMsOverride;
-        if (auto command = CurOp::get(opCtx)->getCommand();
-            command && (command->getName() == "hello" || command->getName() == "isMaster")) {
-            slowMsOverride =
-                2 * durationCount<Milliseconds>(SingleServerIsMasterMonitor::kMaxAwaitTime);
-        }
-
         // Mark the op as complete, populate the response length, and log it if appropriate.
         CurOp::get(opCtx)->completeAndLogOperation(
-            opCtx, logv2::LogComponent::kCommand, dbResponse.response.size(), slowMsOverride);
+            opCtx, logv2::LogComponent::kCommand, dbResponse.response.size());
 
         return dbResponse;
     }