SERVER-41513 Track the time the new term oplog entry was written by primary and applied in secondary

8 files changed, 81 insertions, 17 deletions

diff --git a/src/mongo/db/repl/oplog_applier_impl.cpp b/src/mongo/db/repl/oplog_applier_impl.cpp
index 97b9d37797f..5dc25227e47 100644
--- a/src/mongo/db/repl/oplog_applier_impl.cpp
+++ b/src/mongo/db/repl/oplog_applier_impl.cpp
@@ -43,6 +43,7 @@
 #include "mongo/db/logical_session_id.h"
 #include "mongo/db/repl/apply_ops.h"
 #include "mongo/db/repl/insert_group.h"
+#include "mongo/db/repl/replication_metrics.h"
 #include "mongo/db/repl/transaction_oplog_application.h"
 #include "mongo/db/stats/timer_stats.h"
 #include "mongo/platform/basic.h"
@@ -972,6 +973,16 @@ Status applyOplogEntryBatch(OperationContext* opCtx,
 
     if (opType == OpTypeEnum::kNoop) {
         incrementOpsAppliedStats();
+
+        auto opObj = op.getObject();
+        if (opObj.hasField(ReplicationCoordinator::newPrimaryMsgField) &&
+            opObj.getField(ReplicationCoordinator::newPrimaryMsgField).str() ==
+                ReplicationCoordinator::newPrimaryMsg) {
+
+            ReplicationMetrics::get(opCtx).setParticipantNewTermDates(op.getWallClockTime(),
+                                                                      applyStartTime);
+        }
+
         return Status::OK();
     } else if (OplogEntry::isCrudOpType(opType)) {
         return finishApply(writeConflictRetry(opCtx, "applyOplogEntryBatch_CRUD", nss.ns(), [&] {
diff --git a/src/mongo/db/repl/replication_coordinator.h b/src/mongo/db/repl/replication_coordinator.h
index 63d51768d53..8bc865775b0 100644
--- a/src/mongo/db/repl/replication_coordinator.h
+++ b/src/mongo/db/repl/replication_coordinator.h
@@ -930,6 +930,16 @@ public:
      */
     virtual void finishRecoveryIfEligible(OperationContext* opCtx) = 0;
 
+    /**
+     * Field name of the newPrimaryMsg within the 'o' field in the new term oplog entry.
+     */
+    inline static constexpr StringData newPrimaryMsgField = "msg"_sd;
+
+    /**
+     * Message string passed in the new term oplog entry after a primary has stepped up.
+     */
+    inline static constexpr StringData newPrimaryMsg = "new primary"_sd;
+
 protected:
     ReplicationCoordinator();
 };
diff --git a/src/mongo/db/repl/replication_coordinator_external_state_impl.cpp b/src/mongo/db/repl/replication_coordinator_external_state_impl.cpp
index 5be36ed3881..e7489542f40 100644
--- a/src/mongo/db/repl/replication_coordinator_external_state_impl.cpp
+++ b/src/mongo/db/repl/replication_coordinator_external_state_impl.cpp
@@ -450,8 +450,8 @@ OpTime ReplicationCoordinatorExternalStateImpl::onTransitionToPrimary(OperationC
         WriteUnitOfWork wuow(opCtx);
         opCtx->getClient()->getServiceContext()->getOpObserver()->onOpMessage(
             opCtx,
-            BSON("msg"
-                 << "new primary"));
+            BSON(ReplicationCoordinator::newPrimaryMsgField
+                 << ReplicationCoordinator::newPrimaryMsg));
         wuow.commit();
     });
     const auto loadLastOpTimeAndWallTimeResult = loadLastOpTimeAndWallTime(opCtx);
@@ -459,7 +459,7 @@ OpTime ReplicationCoordinatorExternalStateImpl::onTransitionToPrimary(OperationC
     auto opTimeToReturn = loadLastOpTimeAndWallTimeResult.getValue().opTime;
 
     auto newTermStartDate = loadLastOpTimeAndWallTimeResult.getValue().wallTime;
-    ReplicationMetrics::get(opCtx).setNewTermStartDate(newTermStartDate);
+    ReplicationMetrics::get(opCtx).setCandidateNewTermStartDate(newTermStartDate);
 
     auto replCoord = ReplicationCoordinator::get(opCtx);
     replCoord->createWMajorityWriteAvailabilityDateWaiter(opTimeToReturn);
diff --git a/src/mongo/db/repl/replication_coordinator_impl.cpp b/src/mongo/db/repl/replication_coordinator_impl.cpp
index 8925e576199..a15e1944f92 100644
--- a/src/mongo/db/repl/replication_coordinator_impl.cpp
+++ b/src/mongo/db/repl/replication_coordinator_impl.cpp
@@ -3757,7 +3757,9 @@ Status ReplicationCoordinatorImpl::processReplSetRequestVotes(
         const int candidateIndex = args.getCandidateIndex();
         LastVote lastVote{args.getTerm(), candidateIndex};
 
-        if (response->getVoteGranted()) {
+        const bool votedForCandidate = response->getVoteGranted();
+
+        if (votedForCandidate) {
             Status status = _externalState->storeLocalLastVoteDocument(opCtx, lastVote);
             if (!status.isOK()) {
                 error() << "replSetRequestVotes failed to store LastVote document; " << status;
@@ -3767,7 +3769,6 @@ Status ReplicationCoordinatorImpl::processReplSetRequestVotes(
 
         // If the vote was not granted to the candidate, we still want to track metrics around the
         // node's participation in the election.
-        const bool votedForCandidate = response->getVoteGranted();
         const long long electionTerm = args.getTerm();
         const Date_t lastVoteDate = _replExecutor->now();
         const int electionCandidateMemberId =
@@ -3926,6 +3927,10 @@ EventHandle ReplicationCoordinatorImpl::_updateTerm_inlock(
     auto now = _replExecutor->now();
     TopologyCoordinator::UpdateTermResult localUpdateTermResult = _topCoord->updateTerm(term, now);
     if (localUpdateTermResult == TopologyCoordinator::UpdateTermResult::kUpdatedTerm) {
+        // When the node discovers a new term, the new term date metrics are now out-of-date, so we
+        // clear them.
+        ReplicationMetrics::get(getServiceContext()).clearParticipantNewTermDates();
+
         _termShadow.store(term);
         _cancelPriorityTakeover_inlock();
         _cancelAndRescheduleElectionTimeout_inlock();
diff --git a/src/mongo/db/repl/replication_metrics.cpp b/src/mongo/db/repl/replication_metrics.cpp
index 2eef9206b55..addb4f7027d 100644
--- a/src/mongo/db/repl/replication_metrics.cpp
+++ b/src/mongo/db/repl/replication_metrics.cpp
@@ -300,7 +300,7 @@ void ReplicationMetrics::setNumCatchUpOps(long numCatchUpOps) {
     _updateAverageCatchUpOps(lk);
 }
 
-void ReplicationMetrics::setNewTermStartDate(Date_t newTermStartDate) {
+void ReplicationMetrics::setCandidateNewTermStartDate(Date_t newTermStartDate) {
     stdx::lock_guard<Latch> lk(_mutex);
     _electionCandidateMetrics.setNewTermStartDate(newTermStartDate);
 }
@@ -328,6 +328,15 @@ BSONObj ReplicationMetrics::getElectionCandidateMetricsBSON() {
     return BSONObj();
 }
 
+void ReplicationMetrics::clearElectionCandidateMetrics() {
+    stdx::lock_guard<Latch> lk(_mutex);
+    _electionCandidateMetrics.setTargetCatchupOpTime(boost::none);
+    _electionCandidateMetrics.setNumCatchUpOps(boost::none);
+    _electionCandidateMetrics.setNewTermStartDate(boost::none);
+    _electionCandidateMetrics.setWMajorityWriteAvailabilityDate(boost::none);
+    _nodeIsCandidateOrPrimary = false;
+}
+
 void ReplicationMetrics::setElectionParticipantMetrics(const bool votedForCandidate,
                                                        const long long electionTerm,
                                                        const Date_t lastVoteDate,
@@ -357,13 +366,17 @@ BSONObj ReplicationMetrics::getElectionParticipantMetricsBSON() {
     return BSONObj();
 }
 
-void ReplicationMetrics::clearElectionCandidateMetrics() {
+void ReplicationMetrics::setParticipantNewTermDates(Date_t newTermStartDate,
+                                                    Date_t newTermAppliedDate) {
     stdx::lock_guard<Latch> lk(_mutex);
-    _electionCandidateMetrics.setTargetCatchupOpTime(boost::none);
-    _electionCandidateMetrics.setNumCatchUpOps(boost::none);
-    _electionCandidateMetrics.setNewTermStartDate(boost::none);
-    _electionCandidateMetrics.setWMajorityWriteAvailabilityDate(boost::none);
-    _nodeIsCandidateOrPrimary = false;
+    _electionParticipantMetrics.setNewTermStartDate(newTermStartDate);
+    _electionParticipantMetrics.setNewTermAppliedDate(newTermAppliedDate);
+}
+
+void ReplicationMetrics::clearParticipantNewTermDates() {
+    stdx::lock_guard<Latch> lk(_mutex);
+    _electionParticipantMetrics.setNewTermStartDate(boost::none);
+    _electionParticipantMetrics.setNewTermAppliedDate(boost::none);
 }
 
 void ReplicationMetrics::_updateAverageCatchUpOps(WithLock lk) {
diff --git a/src/mongo/db/repl/replication_metrics.h b/src/mongo/db/repl/replication_metrics.h
index 24ed57fe5a7..108510bbcd8 100644
--- a/src/mongo/db/repl/replication_metrics.h
+++ b/src/mongo/db/repl/replication_metrics.h
@@ -92,7 +92,7 @@ public:
                                      const boost::optional<int> priorPrimary);
     void setTargetCatchupOpTime(OpTime opTime);
     void setNumCatchUpOps(long numCatchUpOps);
-    void setNewTermStartDate(Date_t newTermStartDate);
+    void setCandidateNewTermStartDate(Date_t newTermStartDate);
     void setWMajorityWriteAvailabilityDate(Date_t wMajorityWriteAvailabilityDate);
 
     boost::optional<OpTime> getTargetCatchupOpTime_forTesting();
@@ -116,6 +116,9 @@ public:
                                        const double priorityAtElection);
 
     BSONObj getElectionParticipantMetricsBSON();
+    void setParticipantNewTermDates(Date_t newTermStartDate, Date_t newTermAppliedDate);
+    void clearParticipantNewTermDates();
+
 
 private:
     class ElectionMetricsSSS;
diff --git a/src/mongo/db/repl/replication_metrics.idl b/src/mongo/db/repl/replication_metrics.idl
index 853ca5d2d5c..4fb062411ed 100644
--- a/src/mongo/db/repl/replication_metrics.idl
+++ b/src/mongo/db/repl/replication_metrics.idl
@@ -208,8 +208,17 @@ structs:
                 description: "Latest applied OpTime at the time of voting"
                 type: optime
             maxAppliedOpTimeInSet:
-                description: "Highest applied time of any node in this replica set, as currently known by this node"
+                description: "Highest applied time of any node in this replica set, as currently
+                              known by this node"
                 type: optime
             priorityAtElection:
                 description: "The node's priority at the time of the election"
                 type: double
+            newTermStartDate:
+                description: "Time the new term oplog entry was written by the primary"
+                type: date
+                optional: true
+            newTermAppliedDate:
+                description: "Time this node applied the new term oplog entry"
+                type: date
+                optional: true
diff --git a/src/mongo/db/repl/topology_coordinator.cpp b/src/mongo/db/repl/topology_coordinator.cpp
index f254d311986..1de492a3eef 100644
--- a/src/mongo/db/repl/topology_coordinator.cpp
+++ b/src/mongo/db/repl/topology_coordinator.cpp
@@ -65,7 +65,8 @@ namespace mongo {
 namespace repl {
 
 MONGO_FAIL_POINT_DEFINE(forceSyncSourceCandidate);
-MONGO_FAIL_POINT_DEFINE(forceVoteInElection);
+MONGO_FAIL_POINT_DEFINE(voteNoInElection);
+MONGO_FAIL_POINT_DEFINE(voteYesInDryRunButNoInRealElection);
 
 // If this fail point is enabled, TopologyCoordinator::shouldChangeSyncSource() will ignore
 // the option TopologyCoordinator::Options::maxSyncSourceLagSecs. The sync source will not be
@@ -2694,13 +2695,25 @@ void TopologyCoordinator::processReplSetRequestVotes(const ReplSetRequestVotesAr
                                                      ReplSetRequestVotesResponse* response) {
     response->setTerm(_term);
 
-    if (MONGO_unlikely(forceVoteInElection.shouldFail())) {
+    if (MONGO_unlikely(voteNoInElection.shouldFail())) {
+        log() << "failpoint voteNoInElection enabled";
+        response->setVoteGranted(false);
+        response->setReason(str::stream() << "forced to vote no during dry run election due to "
+                                             "failpoint voteNoInElection set");
+        return;
+    }
+
+    if (MONGO_unlikely(voteYesInDryRunButNoInRealElection.shouldFail())) {
+        log() << "failpoint voteYesInDryRunButNoInRealElection enabled";
         if (args.isADryRun()) {
             response->setVoteGranted(true);
+            response->setReason(str::stream() << "forced to vote yes in dry run due to failpoint "
+                                                 "voteYesInDryRunButNoInRealElection set");
         } else {
             response->setVoteGranted(false);
             response->setReason(str::stream()
-                                << "forced to vote no due to failpoint forceVoteInElection set");
+                                << "forced to vote no in real election due to failpoint "
+                                   "voteYesInDryRunButNoInRealElection set");
         }
         return;
     }