SERVER-23010: improved logging readconcern usage

5 files changed, 38 insertions, 7 deletions

diff --git a/src/mongo/db/dbcommands.cpp b/src/mongo/db/dbcommands.cpp
index 9d26180677e..a89bb5ac73e 100644
--- a/src/mongo/db/dbcommands.cpp
+++ b/src/mongo/db/dbcommands.cpp
@@ -1426,14 +1426,22 @@ bool Command::run(OperationContext* txn,
                     return result;
                 }
 
+                const int debugLevel =
+                    serverGlobalParams.clusterRole == ClusterRole::ConfigServer ? 1 : 2;
+                LOG(debugLevel) << "Waiting for 'committed' snapshot to be available for reading: "
+                                << readConcernArgs;
                 Status status = txn->recoveryUnit()->setReadFromMajorityCommittedSnapshot();
 
                 // Wait until a snapshot is available.
                 while (status == ErrorCodes::ReadConcernMajorityNotAvailableYet) {
+                    LOG(debugLevel)
+                        << "Snapshot not available for readConcern: " << readConcernArgs;
                     replCoord->waitUntilSnapshotCommitted(txn, SnapshotName::min());
                     status = txn->recoveryUnit()->setReadFromMajorityCommittedSnapshot();
                 }
 
+                LOG(debugLevel) << "Using 'committed' snapshot. " << CurOp::get(txn)->query();
+
                 if (!status.isOK()) {
                     auto result = appendCommandStatus(inPlaceReplyBob, status);
                     inPlaceReplyBob.doneFast();
diff --git a/src/mongo/db/repl/optime.cpp b/src/mongo/db/repl/optime.cpp
index 288826821c2..93c21c22ba1 100644
--- a/src/mongo/db/repl/optime.cpp
+++ b/src/mongo/db/repl/optime.cpp
@@ -72,9 +72,7 @@ BSONObj OpTime::toBSON() const {
 }
 
 std::string OpTime::toString() const {
-    std::stringstream ss;
-    ss << "(term: " << _term << ", timestamp: " << _timestamp.toStringPretty() << ")";
-    return ss.str();
+    return toBSON().toString();
 }
 
 std::ostream& operator<<(std::ostream& out, const OpTime& opTime) {
diff --git a/src/mongo/db/repl/read_concern_args.cpp b/src/mongo/db/repl/read_concern_args.cpp
index 39ffb57251a..097bdc78655 100644
--- a/src/mongo/db/repl/read_concern_args.cpp
+++ b/src/mongo/db/repl/read_concern_args.cpp
@@ -60,6 +60,16 @@ ReadConcernArgs::ReadConcernArgs(boost::optional<OpTime> opTime,
                                  boost::optional<ReadConcernLevel> level)
     : _opTime(std::move(opTime)), _level(std::move(level)) {}
 
+std::string ReadConcernArgs::toString() const {
+    return toBSON().toString();
+}
+
+BSONObj ReadConcernArgs::toBSON() const {
+    BSONObjBuilder bob;
+    appendInfo(&bob);
+    return bob.obj();
+}
+
 ReadConcernLevel ReadConcernArgs::getLevel() const {
     return _level.value_or(ReadConcernLevel::kLocalReadConcern);
 }
diff --git a/src/mongo/db/repl/read_concern_args.h b/src/mongo/db/repl/read_concern_args.h
index 491354ec4f2..5fa9a5fba8c 100644
--- a/src/mongo/db/repl/read_concern_args.h
+++ b/src/mongo/db/repl/read_concern_args.h
@@ -82,6 +82,8 @@ public:
 
     ReadConcernLevel getLevel() const;
     OpTime getOpTime() const;
+    BSONObj toBSON() const;
+    std::string toString() const;
 
 private:
     boost::optional<OpTime> _opTime;
diff --git a/src/mongo/db/repl/replication_coordinator_impl.cpp b/src/mongo/db/repl/replication_coordinator_impl.cpp
index 41ef7d0698b..d598d583d82 100644
--- a/src/mongo/db/repl/replication_coordinator_impl.cpp
+++ b/src/mongo/db/repl/replication_coordinator_impl.cpp
@@ -164,9 +164,13 @@ struct ReplicationCoordinatorImpl::WaiterInfo {
     BSONObj toBSON() const {
         BSONObjBuilder bob;
         bob.append("opId", opID);
-        bob.append("opTime", opTime->toBSON());
+        if (opTime) {
+            bob.append("opTime", opTime->toBSON());
+        }
         bob.append("master", master);
-        bob.append("writeConcern", writeConcern);
+        if (writeConcern) {
+            bob.append("writeConcern", writeConcern->toBSON());
+        }
         return bob.obj();
     };
 
@@ -1053,6 +1057,10 @@ ReadConcernResponse ReplicationCoordinatorImpl::waitUntilOpTime(OperationContext
             : targetOpTime > _getMyLastAppliedOpTime_inlock();
     };
 
+    if (isMajorityReadConcern && loopCondition()) {
+        LOG(1) << "waitUntilOpTime: waiting for optime:" << targetOpTime
+               << " to be in a snapshot -- current snapshot: " << _currentCommittedSnapshot->opTime;
+    }
     while (loopCondition()) {
         Status interruptedStatus = txn->checkForInterruptNoAssert();
         if (!interruptedStatus.isOK()) {
@@ -1334,10 +1342,15 @@ bool ReplicationCoordinatorImpl::_doneWaitingForReplication_inlock(
             if (getWriteConcernMajorityShouldJournal_inlock()) {
                 // Wait for the "current" snapshot to advance to/past the opTime.
 
+                const auto haveSnapshot = (_currentCommittedSnapshot->opTime >= opTime &&
+                                           _currentCommittedSnapshot->name >= minSnapshot);
+                if (!haveSnapshot) {
+                    log() << "Required snapshot optime: " << opTime << " is not yet part of the "
+                          << "current snapshot: " << *_currentCommittedSnapshot;
+                }
                 // We cannot have this committed snapshot until we have replicated to a majority,
                 // so we can return true here once that requirement is met for durable writes.
-                return (_currentCommittedSnapshot->opTime >= opTime &&
-                        _currentCommittedSnapshot->name >= minSnapshot);
+                return haveSnapshot;
             }
         }
         // Continue and wait for replication to the majority (of voters).