diff options
Diffstat (limited to 'src/mongo/db/repl/topology_coordinator.cpp')
| -rw-r--r-- | src/mongo/db/repl/topology_coordinator.cpp | 395 |
1 files changed, 269 insertions, 126 deletions
diff --git a/src/mongo/db/repl/topology_coordinator.cpp b/src/mongo/db/repl/topology_coordinator.cpp index a4e4ab8f9e9..fb7d8c65bd3 100644 --- a/src/mongo/db/repl/topology_coordinator.cpp +++ b/src/mongo/db/repl/topology_coordinator.cpp @@ -53,6 +53,7 @@ #include "mongo/db/repl/isself.h" #include "mongo/db/repl/member_data.h" #include "mongo/db/repl/rslog.h" +#include "mongo/logv2/log.h" #include "mongo/rpc/metadata/oplog_query_metadata.h" #include "mongo/rpc/metadata/repl_set_metadata.h" #include "mongo/util/assert_util.h" @@ -201,7 +202,8 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, ChainingPreference chainingPreference) { // If we are not a member of the current replica set configuration, no sync source is valid. if (_selfIndex == -1) { - LOG(1) << "Cannot sync from any members because we are not in the replica set config"; + LOGV2_DEBUG( + 21778, 1, "Cannot sync from any members because we are not in the replica set config"); return HostAndPort(); } @@ -209,31 +211,38 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, const auto& data = sfp.getData(); const auto hostAndPortElem = data["hostAndPort"]; if (!hostAndPortElem) { - severe() << "'forceSyncSoureCandidate' parameter set with invalid host and port: " - << data; + LOGV2_FATAL( + 21839, + "'forceSyncSoureCandidate' parameter set with invalid host and port: {data}", + "data"_attr = data); fassertFailed(50835); } const auto hostAndPort = HostAndPort(hostAndPortElem.checkAndGetStringData()); const int syncSourceIndex = _rsConfig.findMemberIndexByHostAndPort(hostAndPort); if (syncSourceIndex < 0) { - log() << "'forceSyncSourceCandidate' failed due to host and port not in " - "replica set config: " - << hostAndPort.toString(); + LOGV2(21779, + "'forceSyncSourceCandidate' failed due to host and port not in " + "replica set config: {hostAndPort}", + "hostAndPort"_attr = hostAndPort.toString()); fassertFailed(50836); } if (_memberIsBlacklisted(_rsConfig.getMemberAt(syncSourceIndex), now)) { - log() << "Cannot select a sync source because forced candidate is blacklisted: " - << hostAndPort.toString(); + LOGV2(21780, + "Cannot select a sync source because forced candidate is blacklisted: " + "{hostAndPort}", + "hostAndPort"_attr = hostAndPort.toString()); _syncSource = HostAndPort(); return _syncSource; } _syncSource = _rsConfig.getMemberAt(syncSourceIndex).getHostAndPort(); - log() << "choosing sync source candidate due to 'forceSyncSourceCandidate' parameter: " - << _syncSource; + LOGV2(21781, + "choosing sync source candidate due to 'forceSyncSourceCandidate' parameter: " + "{syncSource}", + "syncSource"_attr = _syncSource); std::string msg(str::stream() << "syncing from: " << _syncSource.toString() << " by 'forceSyncSourceCandidate' parameter"); setMyHeartbeatMessage(now, msg); @@ -245,7 +254,9 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, invariant(_forceSyncSourceIndex < _rsConfig.getNumMembers()); _syncSource = _rsConfig.getMemberAt(_forceSyncSourceIndex).getHostAndPort(); _forceSyncSourceIndex = -1; - log() << "choosing sync source candidate by request: " << _syncSource; + LOGV2(21782, + "choosing sync source candidate by request: {syncSource}", + "syncSource"_attr = _syncSource); std::string msg(str::stream() << "syncing from: " << _syncSource.toString() << " by request"); setMyHeartbeatMessage(now, msg); @@ -258,7 +269,9 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, if (needMorePings > 0) { static Occasionally sampler; if (sampler.tick()) { - log() << "waiting for " << needMorePings << " pings from other members before syncing"; + LOGV2(21783, + "waiting for {needMorePings} pings from other members before syncing", + "needMorePings"_attr = needMorePings); } _syncSource = HostAndPort(); return _syncSource; @@ -268,19 +281,26 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, if (chainingPreference == ChainingPreference::kUseConfiguration && !_rsConfig.isChainingAllowed()) { if (_currentPrimaryIndex == -1) { - LOG(1) << "Cannot select a sync source because chaining is" - " not allowed and primary is unknown/down"; + LOGV2_DEBUG(21784, + 1, + "Cannot select a sync source because chaining is" + " not allowed and primary is unknown/down"); _syncSource = HostAndPort(); return _syncSource; } else if (_memberIsBlacklisted(*_currentPrimaryMember(), now)) { - LOG(1) << "Cannot select a sync source because chaining is not allowed and primary " - "member is blacklisted: " - << _currentPrimaryMember()->getHostAndPort(); + LOGV2_DEBUG(21785, + 1, + "Cannot select a sync source because chaining is not allowed and primary " + "member is blacklisted: {currentPrimaryMember_getHostAndPort}", + "currentPrimaryMember_getHostAndPort"_attr = + _currentPrimaryMember()->getHostAndPort()); _syncSource = HostAndPort(); return _syncSource; } else if (_currentPrimaryIndex == _selfIndex) { - LOG(1) - << "Cannot select a sync source because chaining is not allowed and we are primary"; + LOGV2_DEBUG( + 21786, + 1, + "Cannot select a sync source because chaining is not allowed and we are primary"); _syncSource = HostAndPort(); return _syncSource; } else if (_memberData.at(_currentPrimaryIndex).getLastAppliedOpTime() < @@ -295,8 +315,9 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, return _syncSource; } else { _syncSource = _currentPrimaryMember()->getHostAndPort(); - log() << "chaining not allowed, choosing primary as sync source candidate: " - << _syncSource; + LOGV2(21787, + "chaining not allowed, choosing primary as sync source candidate: {syncSource}", + "syncSource"_attr = _syncSource); std::string msg(str::stream() << "syncing from primary: " << _syncSource.toString()); setMyHeartbeatMessage(now, msg); return _syncSource; @@ -347,14 +368,20 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, // Candidate must be up to be considered. if (!it->up()) { - LOG(2) << "Cannot select sync source because it is not up: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21788, + 2, + "Cannot select sync source because it is not up: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = itMemberConfig.getHostAndPort()); continue; } // Candidate must be PRIMARY or SECONDARY state to be considered. if (!it->getState().readable()) { - LOG(2) << "Cannot select sync source because it is not readable: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21789, + 2, + "Cannot select sync source because it is not readable: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = itMemberConfig.getHostAndPort()); continue; } @@ -362,61 +389,94 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, if (attempts == 0) { // Candidate must be a voter if we are a voter. if (_selfConfig().isVoter() && !itMemberConfig.isVoter()) { - LOG(2) << "Cannot select sync source because we are a voter and it is not: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21790, + 2, + "Cannot select sync source because we are a voter and it is not: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = + itMemberConfig.getHostAndPort()); continue; } // Candidates must not be hidden. if (itMemberConfig.isHidden()) { - LOG(2) << "Cannot select sync source because it is hidden: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21791, + 2, + "Cannot select sync source because it is hidden: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = + itMemberConfig.getHostAndPort()); continue; } // Candidates cannot be excessively behind. if (it->getHeartbeatAppliedOpTime() < oldestSyncOpTime) { - LOG(2) << "Cannot select sync source because it is too far behind." - << "Latest optime of sync candidate " << itMemberConfig.getHostAndPort() - << ": " << it->getHeartbeatAppliedOpTime() - << ", oldest acceptable optime: " << oldestSyncOpTime; + LOGV2_DEBUG( + 21792, + 2, + "Cannot select sync source because it is too far behind.Latest optime of " + "sync candidate {itMemberConfig_getHostAndPort}: " + "{it_getHeartbeatAppliedOpTime}, oldest acceptable optime: " + "{oldestSyncOpTime}", + "itMemberConfig_getHostAndPort"_attr = itMemberConfig.getHostAndPort(), + "it_getHeartbeatAppliedOpTime"_attr = it->getHeartbeatAppliedOpTime(), + "oldestSyncOpTime"_attr = oldestSyncOpTime); continue; } // Candidate must not have a configured delay larger than ours. if (_selfConfig().getSlaveDelay() < itMemberConfig.getSlaveDelay()) { - LOG(2) << "Cannot select sync source with larger slaveDelay than ours: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21793, + 2, + "Cannot select sync source with larger slaveDelay than ours: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = + itMemberConfig.getHostAndPort()); continue; } } // Candidate must build indexes if we build indexes, to be considered. if (_selfConfig().shouldBuildIndexes()) { if (!itMemberConfig.shouldBuildIndexes()) { - LOG(2) << "Cannot select sync source with shouldBuildIndex differences: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21794, + 2, + "Cannot select sync source with shouldBuildIndex differences: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = + itMemberConfig.getHostAndPort()); continue; } } // Only select a candidate that is ahead of me. if (it->getHeartbeatAppliedOpTime() <= lastOpTimeFetched) { - LOG(1) << "Cannot select this sync source. Sync source must be ahead of me. " - << "Sync candidate: " << itMemberConfig.getHostAndPort() - << ", my last fetched oplog optime: " << lastOpTimeFetched.toBSON() - << ", latest oplog optime of sync candidate: " - << it->getHeartbeatAppliedOpTime().toBSON(); + LOGV2_DEBUG(21795, + 1, + "Cannot select this sync source. Sync source must be ahead of me. Sync " + "candidate: {itMemberConfig_getHostAndPort}, my last fetched oplog " + "optime: {lastOpTimeFetched}, latest oplog optime of sync candidate: " + "{it_getHeartbeatAppliedOpTime}", + "itMemberConfig_getHostAndPort"_attr = itMemberConfig.getHostAndPort(), + "lastOpTimeFetched"_attr = lastOpTimeFetched.toBSON(), + "it_getHeartbeatAppliedOpTime"_attr = + it->getHeartbeatAppliedOpTime().toBSON()); continue; } // Candidate cannot be more latent than anything we've already considered. if ((closestIndex != -1) && (_getPing(itMemberConfig.getHostAndPort()) > _getPing(_rsConfig.getMemberAt(closestIndex).getHostAndPort()))) { - LOG(2) << "Cannot select sync source with higher latency than the best candidate: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21796, + 2, + "Cannot select sync source with higher latency than the best " + "candidate: {itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = itMemberConfig.getHostAndPort()); continue; } // Candidate cannot be blacklisted. if (_memberIsBlacklisted(itMemberConfig, now)) { - LOG(1) << "Cannot select sync source which is blacklisted: " - << itMemberConfig.getHostAndPort(); + LOGV2_DEBUG(21797, + 1, + "Cannot select sync source which is blacklisted: " + "{itMemberConfig_getHostAndPort}", + "itMemberConfig_getHostAndPort"_attr = itMemberConfig.getHostAndPort()); continue; } @@ -432,7 +492,7 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, std::string msg("could not find member to sync from"); // Only log when we had a valid sync source before if (!_syncSource.empty()) { - log() << msg << rsLog; + LOGV2_OPTIONS(21798, {logv2::LogTag::kRS}, "{msg}", "msg"_attr = msg); } setMyHeartbeatMessage(now, msg); @@ -440,7 +500,7 @@ HostAndPort TopologyCoordinator::chooseNewSyncSource(Date_t now, return _syncSource; } _syncSource = _rsConfig.getMemberAt(closestIndex).getHostAndPort(); - log() << "sync source candidate: " << _syncSource; + LOGV2(21799, "sync source candidate: {syncSource}", "syncSource"_attr = _syncSource); std::string msg(str::stream() << "syncing from: " << _syncSource.toString(), 0); setMyHeartbeatMessage(now, msg); return _syncSource; @@ -458,14 +518,18 @@ bool TopologyCoordinator::_memberIsBlacklisted(const MemberConfig& memberConfig, } void TopologyCoordinator::blacklistSyncSource(const HostAndPort& host, Date_t until) { - LOG(2) << "blacklisting " << host << " until " << until.toString(); + LOGV2_DEBUG(21800, + 2, + "blacklisting {host} until {until}", + "host"_attr = host, + "until"_attr = until.toString()); _syncSourceBlacklist[host] = until; } void TopologyCoordinator::unblacklistSyncSource(const HostAndPort& host, Date_t now) { std::map<HostAndPort, Date_t>::iterator hostItr = _syncSourceBlacklist.find(host); if (hostItr != _syncSourceBlacklist.end() && now >= hostItr->second) { - LOG(2) << "unblacklisting " << host; + LOGV2_DEBUG(21801, 2, "unblacklisting {host}", "host"_attr = host); _syncSourceBlacklist.erase(hostItr); } } @@ -549,9 +613,14 @@ void TopologyCoordinator::prepareSyncFromResponse(const HostAndPort& target, } const OpTime lastOpApplied = getMyLastAppliedOpTime(); if (hbdata.getHeartbeatAppliedOpTime().getSecs() + 10 < lastOpApplied.getSecs()) { - warning() << "attempting to sync from " << target << ", but its latest opTime is " - << hbdata.getHeartbeatAppliedOpTime().getSecs() << " and ours is " - << lastOpApplied.getSecs() << " so this may not work"; + LOGV2_WARNING(21837, + "attempting to sync from {target}, but its latest opTime is " + "{hbdata_getHeartbeatAppliedOpTime_getSecs} and ours is " + "{lastOpApplied_getSecs} so this may not work", + "target"_attr = target, + "hbdata_getHeartbeatAppliedOpTime_getSecs"_attr = + hbdata.getHeartbeatAppliedOpTime().getSecs(), + "lastOpApplied_getSecs"_attr = lastOpApplied.getSecs()); response->append("warning", str::stream() << "requested member \"" << target.toString() << "\" is more than 10 seconds behind us"); @@ -575,8 +644,10 @@ Status TopologyCoordinator::prepareHeartbeatResponseV1(Date_t now, // Verify that replica set names match const std::string rshb = args.getSetName(); if (ourSetName != rshb) { - log() << "replSet set names do not match, ours: " << ourSetName - << "; remote node's: " << rshb; + LOGV2(21802, + "replSet set names do not match, ours: {ourSetName}; remote node's: {rshb}", + "ourSetName"_attr = ourSetName, + "rshb"_attr = rshb); return Status(ErrorCodes::InconsistentReplicaSetNames, str::stream() << "Our set name of " << ourSetName << " does not match name " << rshb << " reported by remote node"); @@ -761,9 +832,9 @@ HeartbeatResponseAction TopologyCoordinator::processHeartbeatResponse( // Could be we got the newer version before we got the response, or the // target erroneously sent us one, even though it isn't newer. if (newConfig.getConfigVersionAndTerm() < currentConfigVersionAndTerm) { - LOG(1) << "Config version from heartbeat was older than ours."; + LOGV2_DEBUG(21803, 1, "Config version from heartbeat was older than ours."); } else { - LOG(2) << "Config from heartbeat response was same as ours."; + LOGV2_DEBUG(21804, 2, "Config from heartbeat response was same as ours."); } if (shouldLog(MongoLogDefaultComponent_component, ::mongo::LogstreamBuilder::severityCast(2))) { @@ -785,18 +856,24 @@ HeartbeatResponseAction TopologyCoordinator::processHeartbeatResponse( } // If we're not in the config, we don't need to respond to heartbeats. if (_selfIndex == -1) { - LOG(1) << "Could not find ourself in current config so ignoring heartbeat from " << target - << " -- current config: " << _rsConfig.toBSON(); + LOGV2_DEBUG(21805, + 1, + "Could not find ourself in current config so ignoring heartbeat from {target} " + "-- current config: {rsConfig}", + "target"_attr = target, + "rsConfig"_attr = _rsConfig.toBSON()); HeartbeatResponseAction nextAction = HeartbeatResponseAction::makeNoAction(); nextAction.setNextHeartbeatStartDate(nextHeartbeatStartDate); return nextAction; } const int memberIndex = _rsConfig.findMemberIndexByHostAndPort(target); if (memberIndex == -1) { - LOG(1) << "Could not find " << target - << " in current config so ignoring --" - " current config: " - << _rsConfig.toBSON(); + LOGV2_DEBUG(21806, + 1, + "Could not find {target} in current config so ignoring --" + " current config: {rsConfig}", + "target"_attr = target, + "rsConfig"_attr = _rsConfig.toBSON()); HeartbeatResponseAction nextAction = HeartbeatResponseAction::makeNoAction(); nextAction.setNextHeartbeatStartDate(nextHeartbeatStartDate); return nextAction; @@ -816,13 +893,20 @@ HeartbeatResponseAction TopologyCoordinator::processHeartbeatResponse( else if (hbStats.failed() || (alreadyElapsed >= _rsConfig.getHeartbeatTimeoutPeriod())) { hbData.setDownValues(now, hbResponse.getStatus().reason()); } else { - LOG(3) << "Bad heartbeat response from " << target - << "; trying again; Retries left: " << (hbStats.retriesLeft()) << "; " - << alreadyElapsed << " have already elapsed"; + LOGV2_DEBUG(21807, + 3, + "Bad heartbeat response from {target}; trying again; Retries left: " + "{hbStats_retriesLeft}; {alreadyElapsed} have already elapsed", + "target"_attr = target, + "hbStats_retriesLeft"_attr = (hbStats.retriesLeft()), + "alreadyElapsed"_attr = alreadyElapsed); } } else { ReplSetHeartbeatResponse hbr = std::move(hbResponse.getValue()); - LOG(3) << "setUpValues: heartbeat response good for member _id:" << member.getId(); + LOGV2_DEBUG(21808, + 3, + "setUpValues: heartbeat response good for member _id:{member_getId}", + "member_getId"_attr = member.getId()); advancedOpTime = hbData.setUpValues(now, std::move(hbr)); } @@ -932,7 +1016,7 @@ HeartbeatResponseAction TopologyCoordinator::checkMemberTimeouts(Date_t now) { } } if (stepdown) { - log() << "can't see a majority of the set, relinquishing primary"; + LOGV2(21809, "can't see a majority of the set, relinquishing primary"); return HeartbeatResponseAction::makeStepDownSelfAction(_selfIndex); } return HeartbeatResponseAction::makeNoAction(); @@ -981,13 +1065,20 @@ std::pair<MemberId, Date_t> TopologyCoordinator::getStalestLiveMember() const { // Already stale. continue; } - LOG(3) << "memberData lastupdate is: " << memberData.getLastUpdate(); + LOGV2_DEBUG(21810, + 3, + "memberData lastupdate is: {memberData_getLastUpdate}", + "memberData_getLastUpdate"_attr = memberData.getLastUpdate()); if (earliestDate > memberData.getLastUpdate()) { earliestDate = memberData.getLastUpdate(); earliestMemberId = memberData.getMemberId(); } } - LOG(3) << "stalest member " << earliestMemberId << " date: " << earliestDate; + LOGV2_DEBUG(21811, + 3, + "stalest member {earliestMemberId} date: {earliestDate}", + "earliestMemberId"_attr = earliestMemberId, + "earliestDate"_attr = earliestDate); return std::make_pair(earliestMemberId, earliestDate); } @@ -1071,10 +1162,15 @@ StatusWith<bool> TopologyCoordinator::setLastOptime(const UpdatePositionArgs::Up return false; } - LOG(2) << "received notification that node with memberID " << memberId - << " in config with version " << args.cfgver - << " has reached optime: " << args.appliedOpTime - << " and is durable through: " << args.durableOpTime; + LOGV2_DEBUG(21812, + 2, + "received notification that node with memberID {memberId} in config with version " + "{args_cfgver} has reached optime: {args_appliedOpTime} and is durable through: " + "{args_durableOpTime}", + "memberId"_attr = memberId, + "args_cfgver"_attr = args.cfgver, + "args_appliedOpTime"_attr = args.appliedOpTime, + "args_durableOpTime"_attr = args.durableOpTime); // If we're in FCV 4.4, allow replSetUpdatePosition commands between config versions. if (!serverGlobalParams.featureCompatibility.isVersion( @@ -1084,7 +1180,7 @@ StatusWith<bool> TopologyCoordinator::setLastOptime(const UpdatePositionArgs::Up << "Received replSetUpdatePosition for node with memberId " << memberId << " whose config version of " << args.cfgver << " doesn't match our config version of " << _rsConfig.getConfigVersion(); - LOG(1) << errmsg; + LOGV2_DEBUG(21813, 1, "{errmsg}", "errmsg"_attr = errmsg); *configVersion = _rsConfig.getConfigVersion(); return Status(ErrorCodes::InvalidReplicaSetConfig, errmsg); } @@ -1099,16 +1195,23 @@ StatusWith<bool> TopologyCoordinator::setLastOptime(const UpdatePositionArgs::Up std::string errmsg = str::stream() << "Received replSetUpdatePosition for node with memberId " << memberId << " which doesn't exist in our config"; - LOG(1) << errmsg; + LOGV2_DEBUG(21814, 1, "{errmsg}", "errmsg"_attr = errmsg); return Status(ErrorCodes::NodeNotFound, errmsg); } invariant(memberId == memberData->getMemberId()); - LOG(3) << "Node with memberID " << memberId << " currently has optime " - << memberData->getLastAppliedOpTime() << " durable through " - << memberData->getLastDurableOpTime() << "; updating to optime " << args.appliedOpTime - << " and durable through " << args.durableOpTime; + LOGV2_DEBUG( + 21815, + 3, + "Node with memberID {memberId} currently has optime {memberData_getLastAppliedOpTime} " + "durable through {memberData_getLastDurableOpTime}; updating to optime " + "{args_appliedOpTime} and durable through {args_durableOpTime}", + "memberId"_attr = memberId, + "memberData_getLastAppliedOpTime"_attr = memberData->getLastAppliedOpTime(), + "memberData_getLastDurableOpTime"_attr = memberData->getLastDurableOpTime(), + "args_appliedOpTime"_attr = args.appliedOpTime, + "args_durableOpTime"_attr = args.durableOpTime); bool advancedOpTime = memberData->advanceLastAppliedOpTimeAndWallTime( {args.appliedOpTime, args.appliedWallTime}, now); @@ -1401,15 +1504,19 @@ void TopologyCoordinator::changeMemberState_forTest(const MemberState& newMember updateConfig(ReplSetConfig(), -1, Date_t()); break; default: - severe() << "Cannot switch to state " << newMemberState; + LOGV2_FATAL(21840, + "Cannot switch to state {newMemberState}", + "newMemberState"_attr = newMemberState); MONGO_UNREACHABLE; } if (getMemberState() != newMemberState.s) { - severe() << "Expected to enter state " << newMemberState << " but am now in " - << getMemberState(); + LOGV2_FATAL(21841, + "Expected to enter state {newMemberState} but am now in {getMemberState}", + "newMemberState"_attr = newMemberState, + "getMemberState"_attr = getMemberState()); MONGO_UNREACHABLE; } - log() << newMemberState; + LOGV2(21816, "{newMemberState}", "newMemberState"_attr = newMemberState); } void TopologyCoordinator::setCurrentPrimary_forTest(int primaryIndex, @@ -1823,13 +1930,13 @@ TopologyCoordinator::prepareFreezeResponse(Date_t now, int secs, BSONObjBuilder* std::string msg = str::stream() << "cannot freeze node when primary or running for election. state: " << (_role == TopologyCoordinator::Role::kLeader ? "Primary" : "Running-Election"); - log() << msg; + LOGV2(21817, "{msg}", "msg"_attr = msg); return Status(ErrorCodes::NotSecondary, msg); } if (secs == 0) { _stepDownUntil = now; - log() << "'unfreezing'"; + LOGV2(21818, "'unfreezing'"); response->append("info", "unfreezing"); return PrepareFreezeResponseResult::kSingleNodeSelfElect; } else { @@ -1837,7 +1944,7 @@ TopologyCoordinator::prepareFreezeResponse(Date_t now, int secs, BSONObjBuilder* response->append("warning", "you really want to freeze for only 1 second?"); _stepDownUntil = std::max(_stepDownUntil, now + Seconds(secs)); - log() << "'freezing' for " << secs << " seconds"; + LOGV2(21819, "'freezing' for {secs} seconds", "secs"_attr = secs); } return PrepareFreezeResponseResult::kNoAction; @@ -1914,7 +2021,10 @@ void TopologyCoordinator::updateConfig(const ReplSetConfig& newConfig, int selfI // Reset term on startup. if (!_rsConfig.isInitialized()) { _term = OpTime::kInitialTerm; - LOG(1) << "Updated term in topology coordinator to " << _term << " due to new config"; + LOGV2_DEBUG(21820, + 1, + "Updated term in topology coordinator to {term} due to new config", + "term"_attr = _term); } _updateHeartbeatDataForReconfig(newConfig, selfIndex, now); @@ -1924,9 +2034,9 @@ void TopologyCoordinator::updateConfig(const ReplSetConfig& newConfig, int selfI if (_role == Role::kLeader) { if (_selfIndex == -1) { - log() << "Could not remain primary because no longer a member of the replica set"; + LOGV2(21821, "Could not remain primary because no longer a member of the replica set"); } else if (!_selfConfig().isElectable()) { - log() << " Could not remain primary because no longer electable"; + LOGV2(21822, " Could not remain primary because no longer electable"); } else { // Don't stepdown if you don't have to. _currentPrimaryIndex = _selfIndex; @@ -2109,7 +2219,9 @@ std::string TopologyCoordinator::_getUnelectableReasonString(const UnelectableRe ss << "node is not a member of a valid replica set configuration"; } if (!hasWrittenToStream) { - severe() << "Invalid UnelectableReasonMask value 0x" << integerToHex(ur); + LOGV2_FATAL(21842, + "Invalid UnelectableReasonMask value 0x{integerToHex_ur}", + "integerToHex_ur"_attr = integerToHex(ur)); fassertFailed(26011); } ss << " (mask 0x" << integerToHex(ur) << ")"; @@ -2422,7 +2534,7 @@ void TopologyCoordinator::finishUnconditionalStepDown() { // two other nodes think they are primary (asynchronously polled) // -- wait for things to settle down. remotePrimaryIndex = -1; - warning() << "two remote primaries (transiently)"; + LOGV2_WARNING(21838, "two remote primaries (transiently)"); break; } remotePrimaryIndex = itIndex; @@ -2494,8 +2606,12 @@ bool TopologyCoordinator::advanceLastCommittedOpTimeAndWallTime(OpTimeAndWallTim // This check is performed to ensure primaries do not commit an OpTime from a previous term. if (_iAmPrimary() && committedOpTime.opTime < _firstOpTimeOfMyTerm) { - LOG(1) << "Ignoring older committed snapshot from before I became primary, optime: " - << committedOpTime.opTime << ", firstOpTimeOfMyTerm: " << _firstOpTimeOfMyTerm; + LOGV2_DEBUG(21823, + 1, + "Ignoring older committed snapshot from before I became primary, optime: " + "{committedOpTime_opTime}, firstOpTimeOfMyTerm: {firstOpTimeOfMyTerm}", + "committedOpTime_opTime"_attr = committedOpTime.opTime, + "firstOpTimeOfMyTerm"_attr = _firstOpTimeOfMyTerm); return false; } @@ -2505,11 +2621,15 @@ bool TopologyCoordinator::advanceLastCommittedOpTimeAndWallTime(OpTimeAndWallTim if (fromSyncSource) { committedOpTime = std::min(committedOpTime, getMyLastAppliedOpTimeAndWallTime()); } else { - LOG(1) << "Ignoring commit point with different term than my lastApplied, since it " - "may " - "not be on the same oplog branch as mine. optime: " - << committedOpTime - << ", my last applied: " << getMyLastAppliedOpTimeAndWallTime(); + LOGV2_DEBUG(21824, + 1, + "Ignoring commit point with different term than my lastApplied, since it " + "may " + "not be on the same oplog branch as mine. optime: {committedOpTime}, my " + "last applied: {getMyLastAppliedOpTimeAndWallTime}", + "committedOpTime"_attr = committedOpTime, + "getMyLastAppliedOpTimeAndWallTime"_attr = + getMyLastAppliedOpTimeAndWallTime()); return false; } } @@ -2519,12 +2639,19 @@ bool TopologyCoordinator::advanceLastCommittedOpTimeAndWallTime(OpTimeAndWallTim } if (committedOpTime.opTime < _lastCommittedOpTimeAndWallTime.opTime) { - LOG(1) << "Ignoring older committed snapshot optime: " << committedOpTime - << ", currentCommittedOpTime: " << _lastCommittedOpTimeAndWallTime; + LOGV2_DEBUG(21825, + 1, + "Ignoring older committed snapshot optime: {committedOpTime}, " + "currentCommittedOpTime: {lastCommittedOpTimeAndWallTime}", + "committedOpTime"_attr = committedOpTime, + "lastCommittedOpTimeAndWallTime"_attr = _lastCommittedOpTimeAndWallTime); return false; } - LOG(2) << "Updating _lastCommittedOpTimeAndWallTime to " << committedOpTime; + LOGV2_DEBUG(21826, + 2, + "Updating _lastCommittedOpTimeAndWallTime to {committedOpTime}", + "committedOpTime"_attr = committedOpTime); _lastCommittedOpTimeAndWallTime = committedOpTime; return true; } @@ -2586,7 +2713,8 @@ TopologyCoordinator::UpdateTermResult TopologyCoordinator::updateTerm(long long if (_iAmPrimary()) { return TopologyCoordinator::UpdateTermResult::kTriggerStepDown; } - LOG(1) << "Updating term from " << _term << " to " << term; + LOGV2_DEBUG( + 21827, 1, "Updating term from {term} to {term2}", "term"_attr = _term, "term2"_attr = term); _term = term; return TopologyCoordinator::UpdateTermResult::kUpdatedTerm; } @@ -2611,15 +2739,17 @@ bool TopologyCoordinator::shouldChangeSyncSource( // progress, return true. if (_selfIndex == -1) { - log() << "Not choosing new sync source because we are not in the config."; + LOGV2(21828, "Not choosing new sync source because we are not in the config."); return false; } // If the user requested a sync source change, return true. if (_forceSyncSourceIndex != -1) { - log() << "Choosing new sync source because the user has requested to use " - << _rsConfig.getMemberAt(_forceSyncSourceIndex).getHostAndPort() - << " as a sync source"; + LOGV2(21829, + "Choosing new sync source because the user has requested to use " + "{rsConfig_getMemberAt_forceSyncSourceIndex_getHostAndPort} as a sync source", + "rsConfig_getMemberAt_forceSyncSourceIndex_getHostAndPort"_attr = + _rsConfig.getMemberAt(_forceSyncSourceIndex).getHostAndPort()); return true; } @@ -2628,9 +2758,13 @@ bool TopologyCoordinator::shouldChangeSyncSource( if (!serverGlobalParams.featureCompatibility.isVersion( ServerGlobalParams::FeatureCompatibility::Version::kFullyUpgradedTo44)) { if (replMetadata.getConfigVersion() != _rsConfig.getConfigVersion()) { - log() << "Choosing new sync source because the config version supplied by " - << currentSource << ", " << replMetadata.getConfigVersion() - << ", does not match ours, " << _rsConfig.getConfigVersion(); + LOGV2( + 21830, + "Choosing new sync source because the config version supplied by {currentSource}, " + "{replMetadata_getConfigVersion}, does not match ours, {rsConfig_getConfigVersion}", + "currentSource"_attr = currentSource, + "replMetadata_getConfigVersion"_attr = replMetadata.getConfigVersion(), + "rsConfig_getConfigVersion"_attr = _rsConfig.getConfigVersion()); return true; } } @@ -2639,8 +2773,9 @@ bool TopologyCoordinator::shouldChangeSyncSource( // from a node that is not in our config. const int currentSourceIndex = _rsConfig.findMemberIndexByHostAndPort(currentSource); if (currentSourceIndex == -1) { - log() << "Choosing new sync source because " << currentSource.toString() - << " is not in our config"; + LOGV2(21831, + "Choosing new sync source because {currentSource} is not in our config", + "currentSource"_attr = currentSource.toString()); return true; } @@ -2689,15 +2824,17 @@ bool TopologyCoordinator::shouldChangeSyncSource( } else { logMessage << " (sync source does not know the primary)"; } - log() << logMessage.str(); + LOGV2(21832, "{logMessage_str}", "logMessage_str"_attr = logMessage.str()); return true; } if (MONGO_unlikely(disableMaxSyncSourceLagSecs.shouldFail())) { - log() << "disableMaxSyncSourceLagSecs fail point enabled - not checking the most recent " - "OpTime, " - << currentSourceOpTime.toString() << ", of our current sync source, " << currentSource - << ", against the OpTimes of the other nodes in this replica set."; + LOGV2(21833, + "disableMaxSyncSourceLagSecs fail point enabled - not checking the most recent " + "OpTime, {currentSourceOpTime}, of our current sync source, {currentSource}, against " + "the OpTimes of the other nodes in this replica set.", + "currentSourceOpTime"_attr = currentSourceOpTime.toString(), + "currentSource"_attr = currentSource); } else { unsigned int currentSecs = currentSourceOpTime.getSecs(); unsigned int goalSecs = currentSecs + durationCount<Seconds>(_options.maxSyncSourceLagSecs); @@ -2711,13 +2848,19 @@ bool TopologyCoordinator::shouldChangeSyncSource( (candidateConfig.shouldBuildIndexes() || !_selfConfig().shouldBuildIndexes()) && it->getState().readable() && !_memberIsBlacklisted(candidateConfig, now) && goalSecs < it->getHeartbeatAppliedOpTime().getSecs()) { - log() << "Choosing new sync source because the most recent OpTime of our sync " - "source, " - << currentSource << ", is " << currentSourceOpTime.toString() - << " which is more than " << _options.maxSyncSourceLagSecs - << " behind member " << candidateConfig.getHostAndPort().toString() - << " whose most recent OpTime is " - << it->getHeartbeatAppliedOpTime().toString(); + LOGV2( + 21834, + "Choosing new sync source because the most recent OpTime of our sync " + "source, {currentSource}, is {currentSourceOpTime} which is more than " + "{options_maxSyncSourceLagSecs} behind member {candidateConfig_getHostAndPort} " + "whose most recent OpTime is {it_getHeartbeatAppliedOpTime}", + "currentSource"_attr = currentSource, + "currentSourceOpTime"_attr = currentSourceOpTime.toString(), + "options_maxSyncSourceLagSecs"_attr = _options.maxSyncSourceLagSecs, + "candidateConfig_getHostAndPort"_attr = + candidateConfig.getHostAndPort().toString(), + "it_getHeartbeatAppliedOpTime"_attr = + it->getHeartbeatAppliedOpTime().toString()); invariant(itIndex != _selfIndex); return true; } @@ -2751,7 +2894,7 @@ void TopologyCoordinator::processReplSetRequestVotes(const ReplSetRequestVotesAr response->setTerm(_term); if (MONGO_unlikely(voteNoInElection.shouldFail())) { - log() << "failpoint voteNoInElection enabled"; + LOGV2(21835, "failpoint voteNoInElection enabled"); response->setVoteGranted(false); response->setReason(str::stream() << "forced to vote no during dry run election due to " "failpoint voteNoInElection set"); @@ -2759,7 +2902,7 @@ void TopologyCoordinator::processReplSetRequestVotes(const ReplSetRequestVotesAr } if (MONGO_unlikely(voteYesInDryRunButNoInRealElection.shouldFail())) { - log() << "failpoint voteYesInDryRunButNoInRealElection enabled"; + LOGV2(21836, "failpoint voteYesInDryRunButNoInRealElection enabled"); if (args.isADryRun()) { response->setVoteGranted(true); response->setReason(str::stream() << "forced to vote yes in dry run due to failpoint " |