SERVER-27908 Log every heartbeat during testing

6 files changed, 67 insertions, 14 deletions

diff --git a/buildscripts/resmokelib/core/programs.py b/buildscripts/resmokelib/core/programs.py
index e4cadc8e006..a406cd4be45 100644
--- a/buildscripts/resmokelib/core/programs.py
+++ b/buildscripts/resmokelib/core/programs.py
@@ -32,6 +32,10 @@ def mongod_program(logger, executable=None, process_kwargs=None, **kwargs):
     if config.MONGOD_SET_PARAMETERS is not None:
         suite_set_parameters.update(utils.load_yaml(config.MONGOD_SET_PARAMETERS))
 
+    # Turn on replication heartbeat logging.
+    if "replSet" in kwargs and "logComponentVerbosity" not in suite_set_parameters:
+        suite_set_parameters["logComponentVerbosity"] = {"replication": {"heartbeats": 2}}
+
     _apply_set_parameters(args, suite_set_parameters)
 
     shortcut_opts = {
diff --git a/src/mongo/db/repl/repl_set_commands.cpp b/src/mongo/db/repl/repl_set_commands.cpp
index 2001f60a3a8..ab756559784 100644
--- a/src/mongo/db/repl/repl_set_commands.cpp
+++ b/src/mongo/db/repl/repl_set_commands.cpp
@@ -27,6 +27,8 @@
 */
 
 #define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kCommand
+#define LOG_FOR_HEARTBEATS(level) \
+    MONGO_LOG_COMPONENT(level, ::mongo::logger::LogComponent::kReplicationHeartbeats)
 
 #include "mongo/platform/basic.h"
 
@@ -730,6 +732,9 @@ public:
             sleepsecs(data["delay"].numberInt());
         }
 
+        LOG_FOR_HEARTBEATS(2) << "Received heartbeat request from " << cmdObj.getStringField("from")
+                              << ", " << cmdObj;
+
         Status status = Status(ErrorCodes::InternalError, "status not set in heartbeat code");
         /* we don't call ReplSetCommand::check() here because heartbeat
            checks many things that are pre-initialization. */
@@ -764,6 +769,10 @@ public:
                 status = getGlobalReplicationCoordinator()->processHeartbeatV1(args, &response);
                 if (status.isOK())
                     response.addToBSON(&result, true);
+
+                LOG_FOR_HEARTBEATS(2) << "Processed heartbeat from "
+                                      << cmdObj.getStringField("from")
+                                      << " and generated response, " << response;
                 return appendCommandStatus(result, status);
             }
             // else: fall through to old heartbeat protocol as it is likely that
@@ -785,6 +794,9 @@ public:
         status = getGlobalReplicationCoordinator()->processHeartbeat(args, &response);
         if (status.isOK())
             response.addToBSON(&result, false);
+
+        LOG_FOR_HEARTBEATS(2) << "Processed heartbeat from " << cmdObj.getStringField("from")
+                              << " and generated response, " << response;
         return appendCommandStatus(result, status);
     }
 } cmdReplSetHeartbeat;
diff --git a/src/mongo/db/repl/replication_coordinator_impl_heartbeat.cpp b/src/mongo/db/repl/replication_coordinator_impl_heartbeat.cpp
index 907fedcc03a..1adb867255e 100644
--- a/src/mongo/db/repl/replication_coordinator_impl_heartbeat.cpp
+++ b/src/mongo/db/repl/replication_coordinator_impl_heartbeat.cpp
@@ -27,6 +27,8 @@
  */
 
 #define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kReplication
+#define LOG_FOR_HEARTBEATS(level) \
+    MONGO_LOG_COMPONENT(level, ::mongo::logger::LogComponent::kReplicationHeartbeats)
 
 #include "mongo/platform/basic.h"
 
@@ -119,13 +121,16 @@ void ReplicationCoordinatorImpl::_doMemberHeartbeat(ReplicationExecutor::Callbac
                    stdx::placeholders::_1,
                    targetIndex);
 
+    LOG_FOR_HEARTBEATS(2) << "Sending heartbeat (requestId: " << request.id << ") to " << target
+                          << ", " << heartbeatObj;
     _trackHeartbeatHandle(_replExecutor.scheduleRemoteCommand(request, callback));
 }
 
 void ReplicationCoordinatorImpl::_scheduleHeartbeatToTarget(const HostAndPort& target,
                                                             int targetIndex,
                                                             Date_t when) {
-    LOG(2) << "Scheduling heartbeat to " << target << " at " << dateToISOStringUTC(when);
+    LOG_FOR_HEARTBEATS(2) << "Scheduling heartbeat to " << target << " at "
+                          << dateToISOStringUTC(when);
     _trackHeartbeatHandle(
         _replExecutor.scheduleWorkAt(when,
                                      stdx::bind(&ReplicationCoordinatorImpl::_doMemberHeartbeat,
@@ -145,11 +150,14 @@ void ReplicationCoordinatorImpl::_handleHeartbeatResponse(
     // Parse and validate the response.  At the end of this step, if responseStatus is OK then
     // hbResponse is valid.
     Status responseStatus = cbData.response.status;
+    const HostAndPort& target = cbData.request.target;
+
     if (responseStatus == ErrorCodes::CallbackCanceled) {
+        LOG_FOR_HEARTBEATS(2) << "Received response to heartbeat (requestId: " << cbData.request.id
+                              << ") from " << target << " but the heartbeat was cancelled.";
         return;
     }
 
-    const HostAndPort& target = cbData.request.target;
     ReplSetHeartbeatResponse hbResponse;
     BSONObj resp;
     if (responseStatus.isOK()) {
@@ -158,6 +166,9 @@ void ReplicationCoordinatorImpl::_handleHeartbeatResponse(
         StatusWith<rpc::ReplSetMetadata> replMetadata =
             rpc::ReplSetMetadata::readFromMetadata(cbData.response.metadata);
 
+        LOG_FOR_HEARTBEATS(2) << "Received response to heartbeat (requestId: " << cbData.request.id
+                              << ") from " << target << ", " << resp;
+
         // Reject heartbeat responses (and metadata) from nodes with mismatched replica set IDs.
         // It is problematic to perform this check in the heartbeat reconfiguring logic because it
         // is possible for two mismatched replica sets to have the same replica set name and
@@ -202,10 +213,8 @@ void ReplicationCoordinatorImpl::_handleHeartbeatResponse(
             cancelAndRescheduleElectionTimeout();
         }
     } else {
-        log() << "Error in heartbeat request to " << target << "; " << responseStatus;
-        if (!resp.isEmpty()) {
-            LOG(3) << "heartbeat response: " << resp;
-        }
+        LOG_FOR_HEARTBEATS(0) << "Error in heartbeat (requestId: " << cbData.request.id << ") to "
+                              << target << ", response status: " << responseStatus;
 
         hbStatusResponse = StatusWith<ReplSetHeartbeatResponse>(responseStatus);
     }
@@ -633,6 +642,8 @@ void ReplicationCoordinatorImpl::_untrackHeartbeatHandle(const CBHandle& handle)
 }
 
 void ReplicationCoordinatorImpl::_cancelHeartbeats_inlock() {
+    LOG_FOR_HEARTBEATS(2) << "Cancelling all heartbeats.";
+
     std::for_each(_heartbeatHandles.begin(),
                   _heartbeatHandles.end(),
                   stdx::bind(&ReplicationExecutor::cancel, &_replExecutor, stdx::placeholders::_1));
diff --git a/src/mongo/logger/log_component.cpp b/src/mongo/logger/log_component.cpp
index ca1e5e73d78..acce381890e 100644
--- a/src/mongo/logger/log_component.cpp
+++ b/src/mongo/logger/log_component.cpp
@@ -75,6 +75,7 @@ LogComponent LogComponent::parent() const {
             DECLARE_LOG_COMPONENT_PARENT(kJournal, kStorage);
             DECLARE_LOG_COMPONENT_PARENT(kASIO, kNetwork);
             DECLARE_LOG_COMPONENT_PARENT(kBridge, kNetwork);
+            DECLARE_LOG_COMPONENT_PARENT(kReplicationHeartbeats, kReplication);
         case kNumLogComponents:
             return kNumLogComponents;
         default:
@@ -105,6 +106,8 @@ StringData LogComponent::toStringData() const {
             return "query"_sd;
         case kReplication:
             return "replication"_sd;
+        case kReplicationHeartbeats:
+            return "heartbeats"_sd;
         case kSharding:
             return "sharding"_sd;
         case kStorage:
@@ -177,6 +180,8 @@ StringData LogComponent::getNameForLog() const {
             return "QUERY   "_sd;
         case kReplication:
             return "REPL    "_sd;
+        case kReplicationHeartbeats:
+            return "REPL_HB "_sd;
         case kSharding:
             return "SHARDING"_sd;
         case kStorage:
diff --git a/src/mongo/logger/log_component.h b/src/mongo/logger/log_component.h
index 28645bf2c4e..9d97a60abc8 100644
--- a/src/mongo/logger/log_component.h
+++ b/src/mongo/logger/log_component.h
@@ -53,6 +53,7 @@ public:
         kNetwork,
         kQuery,
         kReplication,
+        kReplicationHeartbeats,
         kSharding,
         kStorage,
         kJournal,
diff --git a/src/mongo/shell/servers.js b/src/mongo/shell/servers.js
index fc3212ae3cb..8f4ae13ba3f 100644
--- a/src/mongo/shell/servers.js
+++ b/src/mongo/shell/servers.js
@@ -985,22 +985,29 @@ var MongoRunner, _startMongod, startMongoProgram, runMongoProgram, startMongoPro
      * Returns a new argArray with any test-specific arguments added.
      */
     function appendSetParameterArgs(argArray) {
+        function argArrayContains(key) {
+            return (argArray
+                        .filter((val) => {
+                            return typeof val === "string" && val.indexOf(key) === 0;
+                        })
+                        .length > 0);
+        }
+
         // programName includes the version, e.g., mongod-3.2.
         // baseProgramName is the program name without any version information, e.g., mongod.
         var programName = argArray[0];
+
+        // Object containing log component levels for the "logComponentVerbosity" parameter
+        var logComponentVerbosity = {};
+
         var [baseProgramName, programVersion] = programName.split("-");
         if (baseProgramName === 'mongod' || baseProgramName === 'mongos') {
             if (jsTest.options().enableTestCommands) {
                 argArray.push(...['--setParameter', "enableTestCommands=1"]);
                 if (!programVersion || (parseInt(programVersion.split(".")[0]) >= 3 &&
                                         parseInt(programVersion.split(".")[1]) >= 3)) {
-                    if (argArray
-                            .filter((val) => {
-                                return typeof val === "string" &&
-                                    val.indexOf("logComponentVerbosity") === 0;
-                            })
-                            .length === 0) {
-                        argArray.push(...['--setParameter', "logComponentVerbosity={tracking:0}"]);
+                    if (!argArrayContains("logComponentVerbosity")) {
+                        logComponentVerbosity["tracking"] = 0;
                     }
                 }
             }
@@ -1022,7 +1029,6 @@ var MongoRunner, _startMongod, startMongoProgram, runMongoProgram, startMongoPro
             if (jsTest.options().auth) {
                 argArray.push(...['--setParameter', "enableLocalhostAuthBypass=false"]);
             }
-
             // Since options may not be backward compatible, mongos options are not
             // set on older versions, e.g., mongos-3.0.
             if (programName.endsWith('mongos')) {
@@ -1044,9 +1050,15 @@ var MongoRunner, _startMongod, startMongoProgram, runMongoProgram, startMongoPro
                         argArray.push(...['--storageEngine', jsTest.options().storageEngine]);
                     }
                 }
+
                 // Since options may not be backward compatible, mongod options are not
                 // set on older versions, e.g., mongod-3.0.
                 if (programName.endsWith('mongod')) {
+                    // Enable heartbeat logging for replica set nodes.
+                    if (!argArrayContains("logComponentVerbosity")) {
+                        logComponentVerbosity["replication"] = {"heartbeats": 2};
+                    }
+
                     if (jsTest.options().storageEngine === "wiredTiger" ||
                         !jsTest.options().storageEngine) {
                         if (jsTest.options().storageEngineCacheSizeGB) {
@@ -1083,7 +1095,15 @@ var MongoRunner, _startMongod, startMongoProgram, runMongoProgram, startMongoPro
                     }
                 }
             }
+
+            // Add any enabled log components.
+            if (Object.keys(logComponentVerbosity).length > 0) {
+                argArray.push(
+                    ...['--setParameter',
+                        "logComponentVerbosity=" + JSON.stringify(logComponentVerbosity)]);
+            }
         }
+
         return argArray;
     }