SERVER-63200 Add debug logging for OplogOrder unit test

3 files changed, 67 insertions, 23 deletions

diff --git a/src/mongo/db/storage/record_store_test_oplog.cpp b/src/mongo/db/storage/record_store_test_oplog.cpp
index e398d9d2820..368ba88278d 100644
--- a/src/mongo/db/storage/record_store_test_oplog.cpp
+++ b/src/mongo/db/storage/record_store_test_oplog.cpp
@@ -271,6 +271,34 @@ TEST(RecordStoreTestHarness, SeekNearOnNonOplog) {
     ASSERT_EQ(rec->id, RecordId(1));
 }
 
+/**
+ * Stringifies the current 'record', as well as any more records in the 'cursor'. Additionally adds
+ * the latest oplog visibitility timestamp (this is the current oplog read timestamp, but may not
+ * have been the timestamp used by the cursor).
+ */
+std::string stringifyForDebug(OperationContext* opCtx,
+                              boost::optional<Record> record,
+                              SeekableRecordCursor* cursor) {
+    str::stream output;
+
+    auto optOplogReadTimestampInt = opCtx->recoveryUnit()->getOplogVisibilityTs();
+    if (optOplogReadTimestampInt) {
+        output << "Latest oplog visibility timestamp: "
+               << Timestamp(optOplogReadTimestampInt.get());
+    }
+
+    if (record) {
+        output << ". Current record: " << record->id << ", " << record->data.toBson();
+        while (auto nextRecord = cursor->next()) {
+            if (nextRecord) {
+                output << ". Cursor Record: " << nextRecord->id << ", "
+                       << nextRecord->data.toBson();
+            }
+        }
+    }
+
+    return output;
+}
 
 TEST(RecordStoreTestHarness, OplogOrder) {
     std::unique_ptr<RecordStoreHarnessHelper> harnessHelper(newRecordStoreHarnessHelper());
@@ -343,9 +371,10 @@ TEST(RecordStoreTestHarness, OplogOrder) {
             auto opCtx = harnessHelper->newOperationContext(client2.get());
             auto cursor = rs->getCursor(opCtx.get());
             auto record = cursor->seekExact(id1);
-            ASSERT(record);
-            ASSERT_EQ(id1, record->id);
-            ASSERT(!cursor->next());
+            ASSERT(record) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            auto nextRecord = cursor->next();
+            ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
         }
 
         {
@@ -353,9 +382,10 @@ TEST(RecordStoreTestHarness, OplogOrder) {
             auto opCtx = harnessHelper->newOperationContext(client2.get());
             auto cursor = rs->getCursor(opCtx.get());
             auto record = cursor->seekNear(id2);
-            ASSERT(record);
-            ASSERT_EQ(id1, record->id);
-            ASSERT(!cursor->next());
+            ASSERT(record) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            auto nextRecord = cursor->next();
+            ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
         }
 
         {
@@ -363,9 +393,10 @@ TEST(RecordStoreTestHarness, OplogOrder) {
             auto opCtx = harnessHelper->newOperationContext(client2.get());
             auto cursor = rs->getCursor(opCtx.get());
             auto record = cursor->seekNear(id3);
-            ASSERT(record);
-            ASSERT_EQ(id1, record->id);
-            ASSERT(!cursor->next());
+            ASSERT(record) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            auto nextRecord = cursor->next();
+            ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
         }
 
         w1.commit();
@@ -378,10 +409,13 @@ TEST(RecordStoreTestHarness, OplogOrder) {
         auto opCtx = harnessHelper->newOperationContext(client2.get());
         auto cursor = rs->getCursor(opCtx.get());
         auto record = cursor->seekExact(id1);
-        ASSERT_EQ(id1, record->id);
-        ASSERT(cursor->next());
-        ASSERT(cursor->next());
-        ASSERT(!cursor->next());
+        ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+        auto nextRecord = cursor->next();
+        ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
+        nextRecord = cursor->next();
+        ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
+        nextRecord = cursor->next();
+        ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
     }
 
     // Rollback the last two oplog entries, then insert entries with older optimes and ensure that
@@ -430,8 +464,9 @@ TEST(RecordStoreTestHarness, OplogOrder) {
             auto cursor = rs->getCursor(opCtx.get());
             auto record = cursor->seekExact(id1);
             ASSERT(record);
-            ASSERT_EQ(id1, record->id);
-            ASSERT(!cursor->next());
+            ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            auto nextRecord = cursor->next();
+            ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
         }
 
         {
@@ -440,8 +475,9 @@ TEST(RecordStoreTestHarness, OplogOrder) {
             auto cursor = rs->getCursor(opCtx.get());
             auto record = cursor->seekNear(id2);
             ASSERT(record);
-            ASSERT_EQ(id1, record->id);
-            ASSERT(!cursor->next());
+            ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            auto nextRecord = cursor->next();
+            ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
         }
 
         {
@@ -450,8 +486,9 @@ TEST(RecordStoreTestHarness, OplogOrder) {
             auto cursor = rs->getCursor(opCtx.get());
             auto record = cursor->seekNear(id3);
             ASSERT(record);
-            ASSERT_EQ(id1, record->id);
-            ASSERT(!cursor->next());
+            ASSERT_EQ(id1, record->id) << stringifyForDebug(opCtx.get(), record, cursor.get());
+            auto nextRecord = cursor->next();
+            ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
         }
 
         w1.commit();
@@ -464,9 +501,12 @@ TEST(RecordStoreTestHarness, OplogOrder) {
         auto cursor = rs->getCursor(opCtx.get());
         auto record = cursor->seekExact(id1);
         ASSERT_EQ(id1, record->id);
-        ASSERT(cursor->next());
-        ASSERT(cursor->next());
-        ASSERT(!cursor->next());
+        auto nextRecord = cursor->next();
+        ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
+        nextRecord = cursor->next();
+        ASSERT(nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
+        nextRecord = cursor->next();
+        ASSERT(!nextRecord) << stringifyForDebug(opCtx.get(), nextRecord, cursor.get());
     }
 }
 }  // namespace
diff --git a/src/mongo/db/storage/recovery_unit.h b/src/mongo/db/storage/recovery_unit.h
index e53429cb490..80156daeb72 100644
--- a/src/mongo/db/storage/recovery_unit.h
+++ b/src/mongo/db/storage/recovery_unit.h
@@ -484,6 +484,10 @@ public:
         return ReadSource::kNoTimestamp;
     };
 
+    virtual boost::optional<int64_t> getOplogVisibilityTs() {
+        return boost::none;
+    }
+
     /**
      * Pinning informs callers not to change the ReadSource on this RecoveryUnit. Callers are
      * expected to first check isReadSourcePinned before attempting to change the ReadSource. An
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h
index 70b13ffa3f2..2d75b4e54f1 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h
@@ -220,7 +220,7 @@ public:
      */
     void setTxnModified();
 
-    boost::optional<int64_t> getOplogVisibilityTs();
+    boost::optional<int64_t> getOplogVisibilityTs() override;
 
     static WiredTigerRecoveryUnit* get(OperationContext* opCtx) {
         return checked_cast<WiredTigerRecoveryUnit*>(opCtx->recoveryUnit());