SERVER-40848 Add debug logging to investigate difference in opTime returned by insert and changeStreams

3 files changed, 9 insertions, 0 deletions

diff --git a/src/mongo/db/ops/write_ops_exec.cpp b/src/mongo/db/ops/write_ops_exec.cpp
index ba1d5d967ab..5176503ef73 100644
--- a/src/mongo/db/ops/write_ops_exec.cpp
+++ b/src/mongo/db/ops/write_ops_exec.cpp
@@ -166,6 +166,7 @@ public:
             // guard to fire in that case. Operations on the local DB aren't replicated, so they
             // don't need to bump the lastOp.
             replClientInfo().setLastOpToSystemLastOpTime(_opCtx);
+            LOG(5) << "Set last op to system time: " << replClientInfo().getLastOp().getTimestamp();
         }
     }
 
diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp
index e18171f32bf..3b8795c6d5a 100644
--- a/src/mongo/db/service_entry_point_common.cpp
+++ b/src/mongo/db/service_entry_point_common.cpp
@@ -299,6 +299,7 @@ LogicalTime computeOperationTime(OperationContext* opCtx, LogicalTime startOpera
     invariant(isReplSet);
 
     if (startOperationTime == LogicalTime::kUninitialized) {
+        LOG(5) << "startOperationTime is uninitialized";
         return LogicalTime(replCoord->getMyLastAppliedOpTime().getTimestamp());
     }
 
@@ -346,6 +347,9 @@ void appendClusterAndOperationTime(OperationContext* opCtx,
 
         dassert(signedTime.getTime() >= operationTime);
         rpc::LogicalTimeMetadata(signedTime).writeToMetadata(metadataBob);
+
+        LOG(5) << "Appending operationTime to cmd response for authorized client: "
+               << operationTime;
         operationTime.appendAsOperationTime(commandBodyFieldsBob);
 
         return;
@@ -368,6 +372,8 @@ void appendClusterAndOperationTime(OperationContext* opCtx,
 
     dassert(signedTime.getTime() >= operationTime);
     rpc::LogicalTimeMetadata(signedTime).writeToMetadata(metadataBob);
+
+    LOG(5) << "Appending operationTime to cmd response: " << operationTime;
     operationTime.appendAsOperationTime(commandBodyFieldsBob);
 }
 
diff --git a/src/mongo/s/commands/strategy.cpp b/src/mongo/s/commands/strategy.cpp
index f50597ba972..ba45f6cca80 100644
--- a/src/mongo/s/commands/strategy.cpp
+++ b/src/mongo/s/commands/strategy.cpp
@@ -135,10 +135,12 @@ void appendRequiredFieldsToResponse(OperationContext* opCtx, BSONObjBuilder* res
         // Add operationTime.
         auto operationTime = OperationTimeTracker::get(opCtx)->getMaxOperationTime();
         if (operationTime != LogicalTime::kUninitialized) {
+            LOG(5) << "Appending operationTime: " << operationTime.asTimestamp();
             responseBuilder->append(kOperationTime, operationTime.asTimestamp());
         } else if (now != LogicalTime::kUninitialized) {
             // If we don't know the actual operation time, use the cluster time instead. This is
             // safe but not optimal because we can always return a later operation time than actual.
+            LOG(5) << "Appending clusterTime as operationTime " << now.asTimestamp();
             responseBuilder->append(kOperationTime, now.asTimestamp());
         }