From 8602f5f7b69d2ae71ed7a50acfc779ac57eba107 Mon Sep 17 00:00:00 2001 From: Jason Chan Date: Mon, 27 Apr 2020 18:10:13 -0400 Subject: SERVER-47390 Improve styling of Replication log lines (cherry picked from commit c28d271102bcf3484c56ad592065ddae9c73ee5d) --- etc/backports_required_for_multiversion_tests.yml | 2 + .../replsets/disallow_adding_initialized_node1.js | 5 +- .../db/repl/check_quorum_for_config_change.cpp | 66 +++++++++++++++------- .../repl/check_quorum_for_config_change_test.cpp | 21 +++---- src/mongo/db/repl/replication_coordinator_impl.cpp | 8 +-- src/mongo/db/repl/topology_coordinator.cpp | 17 +++--- src/mongo/db/repl/topology_version_observer.cpp | 27 ++++----- 7 files changed, 85 insertions(+), 61 deletions(-) diff --git a/etc/backports_required_for_multiversion_tests.yml b/etc/backports_required_for_multiversion_tests.yml index 9d07967e6dd..9d22db47713 100644 --- a/etc/backports_required_for_multiversion_tests.yml +++ b/etc/backports_required_for_multiversion_tests.yml @@ -63,6 +63,8 @@ replica_sets_multiversion: test_file: jstests/replsets/apply_ops_inserts_do_not_include_fromMigrate_field.js - ticket: SERVER-47190 test_file: jstests/replsets/force_shutdown_primary.js +- ticket: SERVER-47390 + test_file: jstests/replsets/disallow_adding_initialized_node1.js sharding_multiversion: - ticket: SERVER-38691 diff --git a/jstests/replsets/disallow_adding_initialized_node1.js b/jstests/replsets/disallow_adding_initialized_node1.js index 4773c4031bd..7034805b480 100644 --- a/jstests/replsets/disallow_adding_initialized_node1.js +++ b/jstests/replsets/disallow_adding_initialized_node1.js @@ -49,8 +49,9 @@ configA.members.push({_id: 11, host: primaryB.host}); var reconfigResult = assert.commandFailedWithCode(primaryA.adminCommand({replSetReconfig: configA}), ErrorCodes.NewReplicaSetConfigurationIncompatible); -var msgA = 'Our replica set ID of ' + configA.settings.replicaSetId + ' did not match that of ' + - primaryB.host + ', which is ' + configB.settings.replicaSetId; +var msgA = 'Our replica set ID did not match that of our request target, replSetId: ' + + configA.settings.replicaSetId + ', requestTarget: ' + primaryB.host + + ', requestTargetReplSetId: ' + configB.settings.replicaSetId; assert.neq(-1, reconfigResult.errmsg.indexOf(msgA)); var newPrimaryA = replSetA.getPrimary(); diff --git a/src/mongo/db/repl/check_quorum_for_config_change.cpp b/src/mongo/db/repl/check_quorum_for_config_change.cpp index f7d90664a68..f1492f21069 100644 --- a/src/mongo/db/repl/check_quorum_for_config_change.cpp +++ b/src/mongo/db/repl/check_quorum_for_config_change.cpp @@ -189,9 +189,10 @@ void QuorumChecker::_tabulateHeartbeatResponse(const RemoteCommandRequest& reque ++_numResponses; if (!response.isOK()) { LOGV2_WARNING(23722, - "Failed to complete heartbeat request to {request_target}; {response_status}", - "request_target"_attr = request.target, - "response_status"_attr = response.status); + "Failed to complete heartbeat request to {requestTarget}; {responseStatus}", + "Failed to complete heartbeat request to target", + "requestTarget"_attr = request.target, + "responseStatus"_attr = response.status); _badResponses.push_back(std::make_pair(request.target, response.status)); return; } @@ -201,19 +202,24 @@ void QuorumChecker::_tabulateHeartbeatResponse(const RemoteCommandRequest& reque Status hbStatus = hbResp.initialize(resBSON, 0); if (hbStatus.code() == ErrorCodes::InconsistentReplicaSetNames) { - std::string message = str::stream() - << "Our set name did not match that of " << request.target.toString(); - _vetoStatus = Status(ErrorCodes::NewReplicaSetConfigurationIncompatible, message); - LOGV2_WARNING(23723, "{message}", "message"_attr = message); + static constexpr char message[] = "Our set name did not match that of the request target"; + _vetoStatus = + Status(ErrorCodes::NewReplicaSetConfigurationIncompatible, + str::stream() << message << ", requestTarget:" << request.target.toString()); + LOGV2_WARNING(23723, + "Our set name did not match that of {requestTarget}", + message, + "requestTarget"_attr = request.target.toString()); return; } if (!hbStatus.isOK() && hbStatus != ErrorCodes::InvalidReplicaSetConfig) { LOGV2_WARNING( 23724, - "Got error ({hbStatus}) response on heartbeat request to {request_target}; {hbResp}", + "Got error ({hbStatus}) response on heartbeat request to {requestTarget}; {hbResp}", + "Got error response on heartbeat request", "hbStatus"_attr = hbStatus, - "request_target"_attr = request.target, + "requestTarget"_attr = request.target, "hbResp"_attr = hbResp); _badResponses.push_back(std::make_pair(request.target, hbStatus)); return; @@ -221,12 +227,20 @@ void QuorumChecker::_tabulateHeartbeatResponse(const RemoteCommandRequest& reque if (!hbResp.getReplicaSetName().empty()) { if (hbResp.getConfigVersion() >= _rsConfig->getConfigVersion()) { - std::string message = str::stream() - << "Our config version of " << _rsConfig->getConfigVersion() - << " is no larger than the version on " << request.target.toString() - << ", which is " << hbResp.getConfigVersion(); - _vetoStatus = Status(ErrorCodes::NewReplicaSetConfigurationIncompatible, message); - LOGV2_WARNING(23725, "{message}", "message"_attr = message); + static constexpr char message[] = + "Our config version is no larger than the version of the request target"; + _vetoStatus = Status( + ErrorCodes::NewReplicaSetConfigurationIncompatible, + str::stream() << message << ", rsConfigVersion: " << _rsConfig->getConfigVersion() + << ", requestTarget: " << request.target.toString() + << ", requestTargetConfigVersion: " << hbResp.getConfigVersion()); + LOGV2_WARNING(23725, + "Our config version of {rsConfigVersion} is no larger than the version " + "on {requestTarget}, which is {requestTargetConfigVersion}", + message, + "rsConfigVersion"_attr = _rsConfig->getConfigVersion(), + "requestTarget"_attr = request.target.toString(), + "requestTargetConfigVersion"_attr = hbResp.getConfigVersion()); return; } } @@ -236,12 +250,22 @@ void QuorumChecker::_tabulateHeartbeatResponse(const RemoteCommandRequest& reque rpc::ReplSetMetadata::readFromMetadata(response.data); if (replMetadata.isOK() && replMetadata.getValue().getReplicaSetId().isSet() && _rsConfig->getReplicaSetId() != replMetadata.getValue().getReplicaSetId()) { - std::string message = str::stream() - << "Our replica set ID of " << _rsConfig->getReplicaSetId() - << " did not match that of " << request.target.toString() << ", which is " - << replMetadata.getValue().getReplicaSetId(); - _vetoStatus = Status(ErrorCodes::NewReplicaSetConfigurationIncompatible, message); - LOGV2_WARNING(23726, "{message}", "message"_attr = message); + static constexpr char message[] = + "Our replica set ID did not match that of our request target"; + _vetoStatus = + Status(ErrorCodes::NewReplicaSetConfigurationIncompatible, + str::stream() << message << ", replSetId: " << _rsConfig->getReplicaSetId() + << ", requestTarget: " << request.target.toString() + << ", requestTargetReplSetId: " + << replMetadata.getValue().getReplicaSetId()); + LOGV2_WARNING(23726, + "Our replica set ID of {replSetId} did not match that of " + "{requestTarget}, which is {requestTargetId}", + message, + "replSetId"_attr = _rsConfig->getReplicaSetId(), + "requestTarget"_attr = request.target.toString(), + "requestTargetReplSetId"_attr = + replMetadata.getValue().getReplicaSetId()); } } diff --git a/src/mongo/db/repl/check_quorum_for_config_change_test.cpp b/src/mongo/db/repl/check_quorum_for_config_change_test.cpp index 773be517f3a..b6da250cdad 100644 --- a/src/mongo/db/repl/check_quorum_for_config_change_test.cpp +++ b/src/mongo/db/repl/check_quorum_for_config_change_test.cpp @@ -470,10 +470,11 @@ TEST_F(CheckQuorumForInitiate, QuorumCheckFailedDueToSetIdMismatch) { getNet()->exitNetwork(); Status status = waitForQuorumCheck(); ASSERT_EQUALS(ErrorCodes::NewReplicaSetConfigurationIncompatible, status); - ASSERT_REASON_CONTAINS(status, - str::stream() << "Our replica set ID of " << replicaSetId - << " did not match that of " << incompatibleHost.toString() - << ", which is " << unexpectedId); + ASSERT_REASON_CONTAINS( + status, + str::stream() << "Our replica set ID did not match that of our request target, replSetId: " + << replicaSetId << ", requestTarget: " << incompatibleHost.toString() + << ", requestTargetReplSetId: " << unexpectedId); ASSERT_NOT_REASON_CONTAINS(status, "h1:1"); ASSERT_NOT_REASON_CONTAINS(status, "h2:1"); ASSERT_NOT_REASON_CONTAINS(status, "h3:1"); @@ -531,8 +532,8 @@ TEST_F(CheckQuorumForInitiate, QuorumCheckFailedDueToInitializedNode) { getNet()->exitNetwork(); Status status = waitForQuorumCheck(); ASSERT_EQUALS(ErrorCodes::NewReplicaSetConfigurationIncompatible, status); - ASSERT_REASON_CONTAINS(status, "Our config version of"); - ASSERT_REASON_CONTAINS(status, "is no larger than the version"); + ASSERT_REASON_CONTAINS( + status, "Our config version is no larger than the version of the request target"); ASSERT_NOT_REASON_CONTAINS(status, "h1:1"); ASSERT_NOT_REASON_CONTAINS(status, "h2:1"); ASSERT_NOT_REASON_CONTAINS(status, "h3:1"); @@ -589,8 +590,8 @@ TEST_F(CheckQuorumForInitiate, QuorumCheckFailedDueToInitializedNodeOnlyOneRespo getNet()->exitNetwork(); Status status = waitForQuorumCheck(); ASSERT_EQUALS(ErrorCodes::NewReplicaSetConfigurationIncompatible, status); - ASSERT_REASON_CONTAINS(status, "Our config version of"); - ASSERT_REASON_CONTAINS(status, "is no larger than the version"); + ASSERT_REASON_CONTAINS( + status, "Our config version is no larger than the version of the request target"); ASSERT_NOT_REASON_CONTAINS(status, "h1:1"); ASSERT_NOT_REASON_CONTAINS(status, "h2:1"); ASSERT_NOT_REASON_CONTAINS(status, "h3:1"); @@ -641,8 +642,8 @@ TEST_F(CheckQuorumForReconfig, QuorumCheckVetoedDueToHigherConfigVersion) { getNet()->exitNetwork(); Status status = waitForQuorumCheck(); ASSERT_EQUALS(ErrorCodes::NewReplicaSetConfigurationIncompatible, status); - ASSERT_REASON_CONTAINS(status, "Our config version of"); - ASSERT_REASON_CONTAINS(status, "is no larger than the version"); + ASSERT_REASON_CONTAINS( + status, "Our config version is no larger than the version of the request target"); ASSERT_REASON_CONTAINS(status, "h1:1"); ASSERT_NOT_REASON_CONTAINS(status, "h2:1"); ASSERT_NOT_REASON_CONTAINS(status, "h3:1"); diff --git a/src/mongo/db/repl/replication_coordinator_impl.cpp b/src/mongo/db/repl/replication_coordinator_impl.cpp index 1279437998d..960997ccb72 100644 --- a/src/mongo/db/repl/replication_coordinator_impl.cpp +++ b/src/mongo/db/repl/replication_coordinator_impl.cpp @@ -1944,12 +1944,12 @@ ReplicationCoordinator::StatusAndDuration ReplicationCoordinatorImpl::awaitRepli stdx::lock_guard lock(_mutex); LOGV2(21339, "Replication failed for write concern: {writeConcern}, waiting for optime: {opTime}, " - "opID: {opID}, all_durable: {all_durable}, progress: {progress}", + "opID: {opID}, all_durable: {allDurable}, progress: {progress}", "Replication failed for write concern", "writeConcern"_attr = writeConcern.toBSON(), "opTime"_attr = opTime, "opID"_attr = opCtx->getOpID(), - "all_durable"_attr = _storage->getAllDurableTimestamp(_service), + "allDurable"_attr = _storage->getAllDurableTimestamp(_service), "progress"_attr = _getReplicationProgress(lock)); } return {std::move(status), duration_cast(timer.elapsed())}; @@ -3529,7 +3529,7 @@ Status ReplicationCoordinatorImpl::awaitConfigCommitment(OperationContext* opCtx lk.unlock(); // Wait for the config document to be replicated to a majority of nodes in the current config. - LOGV2(4508702, "Waiting for the current config to propagate to a majority of nodes."); + LOGV2(4508702, "Waiting for the current config to propagate to a majority of nodes"); StatusAndDuration configAwaitStatus = awaitReplication(opCtx, fakeOpTime, _getConfigReplicationWriteConcern()); @@ -3554,7 +3554,7 @@ Status ReplicationCoordinatorImpl::awaitConfigCommitment(OperationContext* opCtx // current config. LOGV2(51815, "Waiting for the last committed optime in the previous config " - "to be committed in the current config.", + "to be committed in the current config", "configOplogCommitmentOpTime"_attr = configOplogCommitmentOpTime); StatusAndDuration oplogAwaitStatus = awaitReplication(opCtx, configOplogCommitmentOpTime, oplogWriteConcern); diff --git a/src/mongo/db/repl/topology_coordinator.cpp b/src/mongo/db/repl/topology_coordinator.cpp index 495a08eec77..96f02005bfb 100644 --- a/src/mongo/db/repl/topology_coordinator.cpp +++ b/src/mongo/db/repl/topology_coordinator.cpp @@ -426,7 +426,7 @@ HostAndPort TopologyCoordinator::_chooseNearbySyncSource(Date_t now, return _syncSource; } _syncSource = _rsConfig.getMemberAt(closestIndex).getHostAndPort(); - LOGV2(21799, "sync source candidate chosen.", "syncSource"_attr = _syncSource); + LOGV2(21799, "Sync source candidate chosen", "syncSource"_attr = _syncSource); std::string msg(str::stream() << "syncing from: " << _syncSource.toString(), 0); setMyHeartbeatMessage(now, msg); return _syncSource; @@ -472,7 +472,6 @@ boost::optional TopologyCoordinator::_chooseSyncSourceInitialStep(D auto syncSource = _rsConfig.getMemberAt(syncSourceIndex).getHostAndPort(); LOGV2(21781, - "choosing sync source candidate due to 'forceSyncSourceCandidate' parameter.", "Choosing sync source candidate due to 'forceSyncSourceCandidate' parameter", "syncSource"_attr = syncSource); std::string msg(str::stream() << "syncing from: " << syncSource.toString() @@ -486,7 +485,7 @@ boost::optional TopologyCoordinator::_chooseSyncSourceInitialStep(D invariant(_forceSyncSourceIndex < _rsConfig.getNumMembers()); auto syncSource = _rsConfig.getMemberAt(_forceSyncSourceIndex).getHostAndPort(); _forceSyncSourceIndex = -1; - LOGV2(21782, "choosing sync source candidate by request", "syncSource"_attr = syncSource); + LOGV2(21782, "Choosing sync source candidate by request", "syncSource"_attr = syncSource); std::string msg(str::stream() << "syncing from: " << syncSource.toString() << " by request"); setMyHeartbeatMessage(now, msg); @@ -518,11 +517,11 @@ HostAndPort TopologyCoordinator::_choosePrimaryAsSyncSource(Date_t now, " the primary is unknown/down."); return HostAndPort(); } else if (_memberIsBlacklisted(*getCurrentPrimaryMember(), now)) { - LOGV2_DEBUG(3873116, - 1, - "Cannot select the primary as sync source because the primary " - "member is blacklisted.", - "primary"_attr = getCurrentPrimaryMember()->getHostAndPort()); + LOGV2_DEBUG( + 3873116, + 1, + "Cannot select the primary as sync source because the primary member is blacklisted", + "primary"_attr = getCurrentPrimaryMember()->getHostAndPort()); return HostAndPort(); } else if (_currentPrimaryIndex == _selfIndex) { LOGV2_DEBUG( @@ -540,7 +539,7 @@ HostAndPort TopologyCoordinator::_choosePrimaryAsSyncSource(Date_t now, return HostAndPort(); } else { auto syncSource = getCurrentPrimaryMember()->getHostAndPort(); - LOGV2(3873117, "Choosing primary as sync source.", "primary"_attr = syncSource); + LOGV2(3873117, "Choosing primary as sync source", "primary"_attr = syncSource); std::string msg(str::stream() << "syncing from primary: " << syncSource.toString()); setMyHeartbeatMessage(now, msg); return syncSource; diff --git a/src/mongo/db/repl/topology_version_observer.cpp b/src/mongo/db/repl/topology_version_observer.cpp index ac1e92fff6d..7f86c1ae6b9 100644 --- a/src/mongo/db/repl/topology_version_observer.cpp +++ b/src/mongo/db/repl/topology_version_observer.cpp @@ -42,9 +42,7 @@ namespace repl { void TopologyVersionObserver::init(ServiceContext* serviceContext, ReplicationCoordinator* replCoordinator) noexcept { - LOGV2_INFO(40440, - "Starting {topologyVersionObserverName}", - "topologyVersionObserverName"_attr = toString()); + LOGV2_INFO(40440, "Starting the TopologyVersionObserver"); stdx::unique_lock lk(_mutex); @@ -73,9 +71,7 @@ void TopologyVersionObserver::shutdown() noexcept { return; } - LOGV2_INFO(40441, - "Stopping {topologyVersionObserverName}", - "topologyVersionObserverName"_attr = toString()); + LOGV2_INFO(40441, "Stopping TopologyVersionObserver"); // Wait for the thread to stop and steal it to the local stack auto thread = [&] { @@ -151,11 +147,16 @@ void TopologyVersionObserver::_cacheIsMasterResponse( // the same purpose. opCtx->sleepFor(kDelayMS); } catch (const ExceptionForCat& e) { - LOGV2_INFO(40443, "Observer was interrupted by {exception}", "exception"_attr = e.toString()); + LOGV2_DEBUG(40443, + 1, + "Observer was interrupted by {error}", + "Observer was interrupted by an exception", + "error"_attr = e.toString()); } catch (DBException& e) { LOGV2_WARNING(40444, - "Observer could not retrieve isMasterResponse: {exception}", - "exception"_attr = e.toString()); + "Observer could not retrieve isMasterResponse: {error}", + "Observer could not retrieve isMasterResponse", + "error"_attr = e.toString()); } void TopologyVersionObserver::_workerThreadBody() noexcept { @@ -171,9 +172,7 @@ void TopologyVersionObserver::_workerThreadBody() noexcept { return boost::none; }; - LOGV2_INFO(40445, - "Started {topologyVersionObserverName}", - "topologyVersionObserverName"_attr = toString()); + LOGV2_INFO(40445, "Started TopologyVersionObserver"); { stdx::lock_guard lk(_mutex); @@ -203,9 +202,7 @@ void TopologyVersionObserver::_workerThreadBody() noexcept { _cv.notify_all(); } - LOGV2_INFO(40447, - "Stopped {topologyVersionObserverName}", - "topologyVersionObserverName"_attr = toString()); + LOGV2_INFO(40447, "Stopped TopologyVersionObserver"); }); stdx::unique_lock lk(_mutex); -- cgit v1.2.1