SERVER-36159 Log whenever the gossiped config server opTime term changes

(cherry picked from commit f6bee9fab63e45bd7ef30e73aff6a21edca16aa2)

8 files changed, 58 insertions, 15 deletions

diff --git a/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.cpp b/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.cpp
index 59f691bed0c..2baf0224828 100644
--- a/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.cpp
+++ b/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.cpp
@@ -55,12 +55,12 @@ repl::OpTime ShardingEgressMetadataHookForMongod::_getConfigServerOpTime() {
     }
 }
 
-Status ShardingEgressMetadataHookForMongod::_advanceConfigOptimeFromShard(
-    ShardId shardId, const BSONObj& metadataObj) {
+Status ShardingEgressMetadataHookForMongod::_advanceConfigOpTimeFromShard(
+    OperationContext* opCtx, const ShardId& shardId, const BSONObj& metadataObj) {
     if (serverGlobalParams.clusterRole == ClusterRole::ConfigServer) {
         return Status::OK();
     }
-    return ShardingEgressMetadataHook::_advanceConfigOptimeFromShard(shardId, metadataObj);
+    return ShardingEgressMetadataHook::_advanceConfigOpTimeFromShard(opCtx, shardId, metadataObj);
 }
 
 }  // namespace rpc
diff --git a/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.h b/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.h
index b010d80bc01..ad09b6e71c3 100644
--- a/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.h
+++ b/src/mongo/db/s/sharding_egress_metadata_hook_for_mongod.h
@@ -44,7 +44,9 @@ private:
 
     repl::OpTime _getConfigServerOpTime() override;
 
-    Status _advanceConfigOptimeFromShard(ShardId shardId, const BSONObj& metadataObj) override;
+    Status _advanceConfigOpTimeFromShard(OperationContext* opCtx,
+                                         const ShardId& shardId,
+                                         const BSONObj& metadataObj) override;
 };
 
 }  // namespace rpc
diff --git a/src/mongo/db/s/sharding_state.cpp b/src/mongo/db/s/sharding_state.cpp
index 9cdce40f044..53e0b28dff0 100644
--- a/src/mongo/db/s/sharding_state.cpp
+++ b/src/mongo/db/s/sharding_state.cpp
@@ -180,7 +180,7 @@ Status ShardingState::updateConfigServerOpTimeFromMetadata(OperationContext* opC
             return Status(ErrorCodes::Unauthorized, "Unauthorized to update config opTime");
         }
 
-        Grid::get(opCtx)->advanceConfigOpTime(*opTime);
+        Grid::get(opCtx)->advanceConfigOpTime(opCtx, *opTime, "request from");
     }
 
     return Status::OK();
diff --git a/src/mongo/db/s/sharding_state_recovery.cpp b/src/mongo/db/s/sharding_state_recovery.cpp
index 76f77d9a0e1..2667c02aedd 100644
--- a/src/mongo/db/s/sharding_state_recovery.cpp
+++ b/src/mongo/db/s/sharding_state_recovery.cpp
@@ -279,7 +279,13 @@ Status ShardingStateRecovery::recover(OperationContext* opCtx) {
 
     if (!recoveryDoc.getMinOpTimeUpdaters()) {
         // Treat the minOpTime as up-to-date
-        grid.advanceConfigOpTime(recoveryDoc.getMinOpTime());
+        const auto prevOpTime = grid.advanceConfigOpTime(
+            opCtx, recoveryDoc.getMinOpTime(), "sharding state recovery document");
+        if (prevOpTime) {
+            log()
+                << "No in flight metadata change operations, so config server optime updated from "
+                << *prevOpTime << " to " << recoveryDoc.getMinOpTime();
+        }
         return Status::OK();
     }
 
diff --git a/src/mongo/s/grid.cpp b/src/mongo/s/grid.cpp
index b81f6565e47..16dfc4914cc 100644
--- a/src/mongo/s/grid.cpp
+++ b/src/mongo/s/grid.cpp
@@ -125,13 +125,32 @@ repl::OpTime Grid::configOpTime() const {
     return _configOpTime;
 }
 
-void Grid::advanceConfigOpTime(repl::OpTime opTime) {
+boost::optional<repl::OpTime> Grid::advanceConfigOpTime(OperationContext* opCtx,
+                                                        repl::OpTime opTime,
+                                                        StringData what) {
+    const auto prevOpTime = _advanceConfigOpTime(opTime);
+    if (prevOpTime && prevOpTime->getTerm() != opTime.getTerm()) {
+        std::string clientAddr = "(unknown)";
+        if (opCtx && opCtx->getClient()) {
+            clientAddr = opCtx->getClient()->clientAddress(true);
+        }
+        log() << "Received " << what << " " << clientAddr << " indicating config server optime "
+                                                             "term has increased, previous optime "
+              << *prevOpTime << ", now " << opTime;
+    }
+    return prevOpTime;
+}
+
+boost::optional<repl::OpTime> Grid::_advanceConfigOpTime(const repl::OpTime& opTime) {
     invariant(serverGlobalParams.clusterRole != ClusterRole::ConfigServer);
 
     stdx::lock_guard<stdx::mutex> lk(_mutex);
     if (_configOpTime < opTime) {
+        repl::OpTime prev = _configOpTime;
         _configOpTime = opTime;
+        return prev;
     }
+    return boost::none;
 }
 
 void Grid::clearForUnitTests() {
diff --git a/src/mongo/s/grid.h b/src/mongo/s/grid.h
index 7df58106677..dad2d10dd16 100644
--- a/src/mongo/s/grid.h
+++ b/src/mongo/s/grid.h
@@ -154,9 +154,12 @@ public:
     /**
      * Called whenever a mongos or shard gets a response from a config server or shard and updates
      * what we've seen as the last config server optime.
+     * If the config optime was updated, returns the previous value.
      * NOTE: This is not valid to call on a config server instance.
      */
-    void advanceConfigOpTime(repl::OpTime opTime);
+    boost::optional<repl::OpTime> advanceConfigOpTime(OperationContext* opCtx,
+                                                      repl::OpTime opTime,
+                                                      StringData what);
 
     /**
      * Clears the grid object so that it can be reused between test executions. This will not
@@ -195,6 +198,13 @@ private:
     // This value is updated any time a shard or mongos talks to a config server or a shard.
     repl::OpTime _configOpTime;
 
+    /**
+     * Called to update what we've seen as the last config server optime.
+     * If the config optime was updated, returns the previous value.
+     * NOTE: This is not valid to call on a config server instance.
+     */
+    boost::optional<repl::OpTime> _advanceConfigOpTime(const repl::OpTime& opTime);
+
     // Deprecated. This is only used on mongos, and once addShard is solely handled by the configs,
     // it can be deleted.
     // Can 'localhost' be used in shard addresses?
diff --git a/src/mongo/s/sharding_egress_metadata_hook.cpp b/src/mongo/s/sharding_egress_metadata_hook.cpp
index 29279cf9d87..82eb3a85b38 100644
--- a/src/mongo/s/sharding_egress_metadata_hook.cpp
+++ b/src/mongo/s/sharding_egress_metadata_hook.cpp
@@ -71,13 +71,14 @@ Status ShardingEgressMetadataHook::readReplyMetadata(OperationContext* opCtx,
                                                      const BSONObj& metadataObj) {
     try {
         _saveGLEStats(metadataObj, replySource);
-        return _advanceConfigOptimeFromShard(replySource.toString(), metadataObj);
+        return _advanceConfigOpTimeFromShard(opCtx, replySource.toString(), metadataObj);
     } catch (...) {
         return exceptionToStatus();
     }
 }
 
-Status ShardingEgressMetadataHook::_advanceConfigOptimeFromShard(ShardId shardId,
+Status ShardingEgressMetadataHook::_advanceConfigOpTimeFromShard(OperationContext* opCtx,
+                                                                 const ShardId& shardId,
                                                                  const BSONObj& metadataObj) {
     auto const grid = Grid::get(_serviceContext);
 
@@ -103,8 +104,8 @@ Status ShardingEgressMetadataHook::_advanceConfigOptimeFromShard(ShardId shardId
                 // due to rollback as explained in SERVER-24630 and the last committed optime
                 // is safe to use.
                 const auto& replMetadata = parseStatus.getValue();
-                auto opTime = replMetadata.getLastOpCommitted();
-                grid->advanceConfigOpTime(opTime);
+                const auto opTime = replMetadata.getLastOpCommitted();
+                grid->advanceConfigOpTime(opCtx, opTime, "reply from config server node");
             }
         } else {
             // Regular shards return the config opTime as part of ConfigServerMetadata.
@@ -114,9 +115,12 @@ Status ShardingEgressMetadataHook::_advanceConfigOptimeFromShard(ShardId shardId
             }
 
             const auto& configMetadata = parseStatus.getValue();
-            auto opTime = configMetadata.getOpTime();
+            const auto opTime = configMetadata.getOpTime();
             if (opTime.is_initialized()) {
-                grid->advanceConfigOpTime(opTime.get());
+                grid->advanceConfigOpTime(opCtx,
+                                          opTime.get(),
+                                          str::stream() << "reply from shard " << shardId
+                                                        << " node");
             }
         }
         return Status::OK();
diff --git a/src/mongo/s/sharding_egress_metadata_hook.h b/src/mongo/s/sharding_egress_metadata_hook.h
index 834ad05c8d4..303e052ca40 100644
--- a/src/mongo/s/sharding_egress_metadata_hook.h
+++ b/src/mongo/s/sharding_egress_metadata_hook.h
@@ -72,7 +72,9 @@ protected:
      * On shards and mongoses this advances the Grid's stored config server optime based on the
      * metadata in the response object from running a command.
      */
-    virtual Status _advanceConfigOptimeFromShard(ShardId shardId, const BSONObj& metadataObj);
+    virtual Status _advanceConfigOpTimeFromShard(OperationContext* opCtx,
+                                                 const ShardId& shardId,
+                                                 const BSONObj& metadataObj);
 
     ServiceContext* const _serviceContext;
 };