SERVER-46666 Add extra validate logging for unit tests for debug proposes

 rename src/mongo/db/storage/{storage_unittest_debug_util.cpp => storage_debug_util.cpp} (73%)
 rename src/mongo/db/storage/{storage_unittest_debug_util.h => storage_debug_util.h} (80%)

12 files changed, 130 insertions, 41 deletions

diff --git a/src/mongo/db/catalog/SConscript b/src/mongo/db/catalog/SConscript
index 6f14a2acd73..e81845269a9 100644
--- a/src/mongo/db/catalog/SConscript
+++ b/src/mongo/db/catalog/SConscript
@@ -369,6 +369,7 @@ env.Library(
         '$BUILD_DIR/mongo/db/logical_clock',
         '$BUILD_DIR/mongo/db/repl/repl_settings',
         '$BUILD_DIR/mongo/db/storage/storage_engine_common',
+        '$BUILD_DIR/mongo/db/storage/storage_debug_util',
         '$BUILD_DIR/mongo/db/transaction',
         'index_build_block',
         'throttle_cursor',
diff --git a/src/mongo/db/catalog/collection_validation.cpp b/src/mongo/db/catalog/collection_validation.cpp
index ffdff6aa52d..76e04d45bd6 100644
--- a/src/mongo/db/catalog/collection_validation.cpp
+++ b/src/mongo/db/catalog/collection_validation.cpp
@@ -430,14 +430,15 @@ Status validate(OperationContext* opCtx,
                 ValidateOptions options,
                 bool background,
                 ValidateResults* results,
-                BSONObjBuilder* output) {
+                BSONObjBuilder* output,
+                bool turnOnExtraLoggingForTest) {
     invariant(!opCtx->lockState()->isLocked() || storageGlobalParams.repair);
     // Background validation does not support any type of full validation.
     invariant(!(background && (options != ValidateOptions::kNoFullValidation)));
 
     // This is deliberately outside of the try-catch block, so that any errors thrown in the
     // constructor fail the cmd, as opposed to returning OK with valid:false.
-    ValidateState validateState(opCtx, nss, background, options);
+    ValidateState validateState(opCtx, nss, background, options, turnOnExtraLoggingForTest);
 
     const auto replCoord = repl::ReplicationCoordinator::get(opCtx);
     // Check whether we are allowed to read from this node after acquiring our locks. If we are
diff --git a/src/mongo/db/catalog/collection_validation.h b/src/mongo/db/catalog/collection_validation.h
index 8809337edd8..fa1b9986589 100644
--- a/src/mongo/db/catalog/collection_validation.h
+++ b/src/mongo/db/catalog/collection_validation.h
@@ -75,7 +75,8 @@ Status validate(OperationContext* opCtx,
                 ValidateOptions options,
                 bool background,
                 ValidateResults* results,
-                BSONObjBuilder* output);
+                BSONObjBuilder* output,
+                bool turnOnExtraLoggingForTest = false);
 
 /**
  * Checks whether a failpoint has been hit in the above validate() code..
diff --git a/src/mongo/db/catalog/index_consistency.cpp b/src/mongo/db/catalog/index_consistency.cpp
index 966b0ada728..ebd4e5900dd 100644
--- a/src/mongo/db/catalog/index_consistency.cpp
+++ b/src/mongo/db/catalog/index_consistency.cpp
@@ -38,6 +38,8 @@
 #include "mongo/db/catalog/index_catalog.h"
 #include "mongo/db/db_raii.h"
 #include "mongo/db/index/index_descriptor.h"
+#include "mongo/db/storage/storage_debug_util.h"
+#include "mongo/logv2/log.h"
 #include "mongo/util/string_map.h"
 
 namespace mongo {
@@ -212,6 +214,15 @@ void IndexConsistency::addDocKey(OperationContext* opCtx,
         // keys encountered.
         _indexKeyCount[hash]++;
         indexInfo->numRecords++;
+
+        if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+            LOGV2(46666002, "[validate](record) {hash_num}", "hash_num"_attr = hash);
+            const BSONObj& keyPatternBson = indexInfo->keyPattern;
+            auto keyStringBson = KeyString::toBsonSafe(
+                ks.getBuffer(), ks.getSize(), indexInfo->ord, ks.getTypeBits());
+            StorageDebugUtil::printKeyString(
+                recordId, ks, keyPatternBson, keyStringBson, "[validate](record)");
+        }
     } else if (_indexKeyCount[hash]) {
         // Found a document key for a hash bucket that had mismatches.
 
@@ -246,6 +257,15 @@ void IndexConsistency::addIndexKey(const KeyString::Value& ks,
         // keys encountered.
         _indexKeyCount[hash]--;
         indexInfo->numKeys++;
+
+        if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+            LOGV2(46666003, "[validate](index) {hash_num}", "hash_num"_attr = hash);
+            const BSONObj& keyPatternBson = indexInfo->keyPattern;
+            auto keyStringBson = KeyString::toBsonSafe(
+                ks.getBuffer(), ks.getSize(), indexInfo->ord, ks.getTypeBits());
+            StorageDebugUtil::printKeyString(
+                recordId, ks, keyPatternBson, keyStringBson, "[validate](index)");
+        }
     } else if (_indexKeyCount[hash]) {
         // Found an index key for a bucket that has inconsistencies.
         // If there is a corresponding document key for the index entry key, we remove the key from
diff --git a/src/mongo/db/catalog/validate_adaptor.cpp b/src/mongo/db/catalog/validate_adaptor.cpp
index 84183e6dce2..a6d5ca72b6b 100644
--- a/src/mongo/db/catalog/validate_adaptor.cpp
+++ b/src/mongo/db/catalog/validate_adaptor.cpp
@@ -69,6 +69,13 @@ Status ValidateAdaptor::validateRecord(OperationContext* opCtx,
         return exceptionToStatus();
     }
 
+    if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+        LOGV2(46666001,
+              "[validate](record) {record_id}, Value: {record_data}",
+              "record_id"_attr = recordId,
+              "record_data"_attr = recordBson);
+    }
+
     const Status status = validateBSON(
         recordBson.objdata(), recordBson.objsize(), Validator<BSONObj>::enabledBSONVersion());
     if (status.isOK()) {
diff --git a/src/mongo/db/catalog/validate_state.cpp b/src/mongo/db/catalog/validate_state.cpp
index f31a3fe8647..aa1b85d4d68 100644
--- a/src/mongo/db/catalog/validate_state.cpp
+++ b/src/mongo/db/catalog/validate_state.cpp
@@ -54,8 +54,13 @@ namespace CollectionValidation {
 ValidateState::ValidateState(OperationContext* opCtx,
                              const NamespaceString& nss,
                              bool background,
-                             ValidateOptions options)
-    : _nss(nss), _background(background), _options(options), _dataThrottle(opCtx) {
+                             ValidateOptions options,
+                             bool turnOnExtraLoggingForTest)
+    : _nss(nss),
+      _background(background),
+      _options(options),
+      _dataThrottle(opCtx),
+      _extraLoggingForTest(turnOnExtraLoggingForTest) {
 
     // Subsequent re-locks will use the UUID when 'background' is true.
     if (_background) {
diff --git a/src/mongo/db/catalog/validate_state.h b/src/mongo/db/catalog/validate_state.h
index e316a850d9b..258fa6ca4c7 100644
--- a/src/mongo/db/catalog/validate_state.h
+++ b/src/mongo/db/catalog/validate_state.h
@@ -55,10 +55,15 @@ class ValidateState {
     ValidateState& operator=(const ValidateState&) = delete;
 
 public:
+    /**
+     * 'turnOnExtraLoggingForTest' turns on extra logging for test debugging. This parameter is for
+     * unit testing only.
+     */
     ValidateState(OperationContext* opCtx,
                   const NamespaceString& nss,
                   bool background,
-                  ValidateOptions options);
+                  ValidateOptions options,
+                  bool turnOnExtraLoggingForTest = false);
 
     const NamespaceString& nss() const {
         return _nss;
@@ -132,6 +137,15 @@ public:
      */
     void initializeCursors(OperationContext* opCtx);
 
+    /**
+     * Indicates whether extra logging should occur during validation.
+     *
+     * This is for unit testing only. Intended to improve diagnosibility.
+     */
+    bool extraLoggingForTest() {
+        return _extraLoggingForTest;
+    }
+
 private:
     ValidateState() = delete;
 
@@ -196,6 +210,9 @@ private:
 
     // Used to detect when the catalog is re-opened while yielding locks.
     uint64_t _catalogGeneration;
+
+    // Can be set by unit tests to obtain better insight into what validate sees/does.
+    bool _extraLoggingForTest;
 };
 
 }  // namespace CollectionValidation
diff --git a/src/mongo/db/storage/SConscript b/src/mongo/db/storage/SConscript
index 520a2229470..963b2fc0196 100644
--- a/src/mongo/db/storage/SConscript
+++ b/src/mongo/db/storage/SConscript
@@ -212,9 +212,9 @@ env.Library(
 )
 
 env.Library(
-    target='storage_unittest_debug_util',
+    target='storage_debug_util',
     source=[
-        'storage_unittest_debug_util.cpp',
+        'storage_debug_util.cpp',
     ],
     LIBDEPS_PRIVATE=[
         '$BUILD_DIR/mongo/db/db_raii',
diff --git a/src/mongo/db/storage/storage_unittest_debug_util.cpp b/src/mongo/db/storage/storage_debug_util.cpp
index 2c0d9243515..64c4bcbc591 100644
--- a/src/mongo/db/storage/storage_unittest_debug_util.cpp
+++ b/src/mongo/db/storage/storage_debug_util.cpp
@@ -31,7 +31,7 @@
 
 #include "mongo/platform/basic.h"
 
-#include "mongo/db/storage/storage_unittest_debug_util.h"
+#include "mongo/db/storage/storage_debug_util.h"
 
 #include "mongo/db/db_raii.h"
 #include "mongo/db/index/index_access_method.h"
@@ -42,6 +42,36 @@ namespace mongo {
 
 namespace StorageDebugUtil {
 
+void printKeyString(const RecordId& recordId,
+                    const KeyString::Value& keyStringValue,
+                    const BSONObj& keyPatternBson,
+                    const BSONObj& keyStringBson,
+                    std::string callerLogPrefix) {
+    // We need to rehydrate the keyString to something readable.
+    auto keyPatternIter = keyPatternBson.begin();
+    auto keyStringIter = keyStringBson.begin();
+    BSONObjBuilder b;
+    while (keyPatternIter != keyPatternBson.end() && keyStringIter != keyStringBson.end()) {
+        b.appendAs(*keyStringIter, keyPatternIter->fieldName());
+        ++keyPatternIter;
+        ++keyStringIter;
+    }
+    // Wildcard index documents can have more values in the keystring.
+    while (keyStringIter != keyStringBson.end()) {
+        b.append(*keyStringIter);
+        ++keyStringIter;
+    }
+    BSONObj rehydratedKey = b.done();
+
+    LOGV2(51811,
+          "{caller} {record_id}, key: {rehydrated_key}, keystring: "
+          "{key_string}",
+          "caller"_attr = callerLogPrefix,
+          "record_id"_attr = recordId,
+          "rehydrated_key"_attr = rehydratedKey,
+          "key_string"_attr = keyStringValue);
+}
+
 void printCollectionAndIndexTableEntries(OperationContext* opCtx, const NamespaceString& nss) {
     invariant(!opCtx->lockState()->isLocked());
     AutoGetCollection autoColl(opCtx, nss, MODE_IS);
@@ -53,10 +83,10 @@ void printCollectionAndIndexTableEntries(OperationContext* opCtx, const Namespac
     RecordStore* rs = coll->getRecordStore();
     auto rsCursor = rs->getCursor(opCtx);
     boost::optional<Record> rec = rsCursor->next();
-    LOGV2(51808, "Collection table entries:");
+    LOGV2(51808, "[Debugging] Collection table entries:");
     while (rec) {
         LOGV2(51809,
-              "{record_id}, Value: {record_data}",
+              "[Debugging](record) {record_id}, Value: {record_data}",
               "record_id"_attr = rec->id,
               "record_data"_attr = rec->data.toBson());
         rec = rsCursor->next();
@@ -77,37 +107,22 @@ void printCollectionAndIndexTableEntries(OperationContext* opCtx, const Namespac
         KeyString::Builder firstKeyString(
             version, BSONObj(), ordering, KeyString::Discriminator::kExclusiveBefore);
 
-        LOGV2(51810, "{keyPattern_str} index table entries:", "keyPattern_str"_attr = keyPattern);
+        LOGV2(51810,
+              "[Debugging] {keyPattern_str} index table entries:",
+              "keyPattern_str"_attr = keyPattern);
 
         for (auto keyStringEntry = indexCursor->seekForKeyString(firstKeyString.getValueCopy());
              keyStringEntry;
              keyStringEntry = indexCursor->nextKeyString()) {
-            // We need to rehydrate the keyString to something readable.
             auto keyString = KeyString::toBsonSafe(keyStringEntry->keyString.getBuffer(),
                                                    keyStringEntry->keyString.getSize(),
                                                    ordering,
                                                    keyStringEntry->keyString.getTypeBits());
-            auto keyPatternIter = keyPattern.begin();
-            auto keyStringIter = keyString.begin();
-            BSONObjBuilder b;
-            while (keyPatternIter != keyPattern.end() && keyStringIter != keyString.end()) {
-                b.appendAs(*keyStringIter, keyPatternIter->fieldName());
-                ++keyPatternIter;
-                ++keyStringIter;
-            }
-            // Wildcard index documents can have more values in the keystring.
-            while (keyStringIter != keyString.end()) {
-                b.append(*keyStringIter);
-                ++keyStringIter;
-            }
-            BSONObj rehydratedKey = b.done();
-
-            LOGV2(51811,
-                  "{keyStringEntry_recId}, key: {rehydrated_key}, keystring: "
-                  "{keyStringEntry_keyString}",
-                  "keyStringEntry_recId"_attr = keyStringEntry->loc,
-                  "rehydrated_key"_attr = rehydratedKey,
-                  "keyStringEntry_keyString"_attr = keyStringEntry->keyString);
+            printKeyString(keyStringEntry->loc,
+                           keyStringEntry->keyString,
+                           keyPattern,
+                           keyString,
+                           "[Debugging](index)");
         }
     }
 }
diff --git a/src/mongo/db/storage/storage_unittest_debug_util.h b/src/mongo/db/storage/storage_debug_util.h
index ca4f249151c..27e6be9a8a4 100644
--- a/src/mongo/db/storage/storage_unittest_debug_util.h
+++ b/src/mongo/db/storage/storage_debug_util.h
@@ -29,10 +29,14 @@
 
 #pragma once
 
+#include "mongo/db/storage/key_string.h"
+
 namespace mongo {
 
+class BSONObj;
 class NamespaceString;
 class OperationContext;
+class RecordId;
 struct ValidateResults;
 
 /**
@@ -41,6 +45,18 @@ struct ValidateResults;
 namespace StorageDebugUtil {
 
 /**
+ * Takes key string and key pattern information and uses it to present human-readable information
+ * about an index or collection entry.
+ *
+ * 'logPrefix' addes a logging prefix. Useful for differentiating callers.
+ */
+void printKeyString(const RecordId& recordId,
+                    const KeyString::Value& keyStringValue,
+                    const BSONObj& keyPatternBson,
+                    const BSONObj& keyStringBson,
+                    std::string callerLogPrefix);
+
+/**
  * Prints all the document entries in the collection table and index tables associated with
  * 'coll'.
  *
diff --git a/src/mongo/dbtests/SConscript b/src/mongo/dbtests/SConscript
index 28097a6453b..8c26c01d965 100644
--- a/src/mongo/dbtests/SConscript
+++ b/src/mongo/dbtests/SConscript
@@ -161,7 +161,7 @@ if not has_option('noshell') and usemozjs:
             "$BUILD_DIR/mongo/db/storage/durable_catalog_impl",
             "$BUILD_DIR/mongo/db/storage/ephemeral_for_test/storage_ephemeral_for_test",
             "$BUILD_DIR/mongo/db/storage/storage_engine_impl",
-            "$BUILD_DIR/mongo/db/storage/storage_unittest_debug_util",
+            "$BUILD_DIR/mongo/db/storage/storage_debug_util",
             "$BUILD_DIR/mongo/db/storage/wiredtiger/storage_wiredtiger" if wiredtiger else [],
             "$BUILD_DIR/mongo/db/transaction",
             "$BUILD_DIR/mongo/shell_core",
diff --git a/src/mongo/dbtests/validate_tests.cpp b/src/mongo/dbtests/validate_tests.cpp
index 275fd35e0eb..36a7f3a5b92 100644
--- a/src/mongo/dbtests/validate_tests.cpp
+++ b/src/mongo/dbtests/validate_tests.cpp
@@ -40,7 +40,7 @@
 #include "mongo/db/index/index_access_method.h"
 #include "mongo/db/index/index_descriptor.h"
 #include "mongo/db/service_context.h"
-#include "mongo/db/storage/storage_unittest_debug_util.h"
+#include "mongo/db/storage/storage_debug_util.h"
 #include "mongo/dbtests/dbtests.h"
 
 namespace ValidateTests {
@@ -48,7 +48,10 @@ namespace ValidateTests {
 using std::unique_ptr;
 
 namespace {
+
 const auto kIndexVersion = IndexDescriptor::IndexVersion::kV2;
+const bool kTurnOnExtraLoggingForTest = true;
+
 }  // namespace
 
 static const char* const _ns = "unittests.validate_tests";
@@ -105,8 +108,8 @@ protected:
         ValidateResults results;
         BSONObjBuilder output;
 
-        ASSERT_OK(
-            CollectionValidation::validate(&_opCtx, _nss, options, _background, &results, &output));
+        ASSERT_OK(CollectionValidation::validate(
+            &_opCtx, _nss, options, _background, &results, &output, kTurnOnExtraLoggingForTest));
 
         //  Check if errors are reported if and only if valid is set to false.
         ASSERT_EQ(results.valid, results.errors.empty());
@@ -1209,7 +1212,8 @@ public:
                 CollectionValidation::ValidateOptions::kFullValidation,
                 _background,
                 &results,
-                &output));
+                &output,
+                kTurnOnExtraLoggingForTest));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1331,7 +1335,8 @@ public:
                 CollectionValidation::ValidateOptions::kFullValidation,
                 _background,
                 &results,
-                &output));
+                &output,
+                kTurnOnExtraLoggingForTest));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1429,7 +1434,8 @@ public:
                 CollectionValidation::ValidateOptions::kFullValidation,
                 _background,
                 &results,
-                &output));
+                &output,
+                kTurnOnExtraLoggingForTest));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);