SERVER-74045 Allow turning on diagnostic log messages for validate

(cherry picked from commit 7230a2aa4f4eedcaa6a0c85c7c14bcb29c63ae93)

12 files changed, 79 insertions, 57 deletions

diff --git a/src/mongo/db/catalog/collection_validation.cpp b/src/mongo/db/catalog/collection_validation.cpp
index fa0379b081b..0eaa4992ad6 100644
--- a/src/mongo/db/catalog/collection_validation.cpp
+++ b/src/mongo/db/catalog/collection_validation.cpp
@@ -425,15 +425,14 @@ Status validate(OperationContext* opCtx,
                 RepairMode repairMode,
                 ValidateResults* results,
                 BSONObjBuilder* output,
-                bool turnOnExtraLoggingForTest) {
+                bool logDiagnostics) {
     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, repairMode, turnOnExtraLoggingForTest);
+    ValidateState validateState(opCtx, nss, background, options, repairMode, logDiagnostics);
 
     // Capped collections perform un-timestamped writes to delete expired documents. As a result,
     // background validation will fail when reading documents that have just been deleted.
diff --git a/src/mongo/db/catalog/collection_validation.h b/src/mongo/db/catalog/collection_validation.h
index 4c9031fed0b..9f7f3c02c9c 100644
--- a/src/mongo/db/catalog/collection_validation.h
+++ b/src/mongo/db/catalog/collection_validation.h
@@ -88,7 +88,7 @@ Status validate(OperationContext* opCtx,
                 RepairMode repairMode,
                 ValidateResults* results,
                 BSONObjBuilder* output,
-                bool turnOnExtraLoggingForTest = false);
+                bool logDiagnostics);
 
 /**
  * Checks whether a failpoint has been hit in the above validate() code..
diff --git a/src/mongo/db/catalog/collection_validation_test.cpp b/src/mongo/db/catalog/collection_validation_test.cpp
index 492b2eb8162..0ecf81c5623 100644
--- a/src/mongo/db/catalog/collection_validation_test.cpp
+++ b/src/mongo/db/catalog/collection_validation_test.cpp
@@ -105,8 +105,14 @@ void foregroundValidate(OperationContext* opCtx,
     for (auto options : optionsList) {
         ValidateResults validateResults;
         BSONObjBuilder output;
-        ASSERT_OK(CollectionValidation::validate(
-            opCtx, kNss, options, /*background*/ false, repairMode, &validateResults, &output));
+        ASSERT_OK(CollectionValidation::validate(opCtx,
+                                                 kNss,
+                                                 options,
+                                                 /*background*/ false,
+                                                 repairMode,
+                                                 &validateResults,
+                                                 &output,
+                                                 /*logDiagnostics=*/false));
         ASSERT_EQ(validateResults.valid, valid);
         ASSERT_EQ(validateResults.errors.size(), static_cast<long unsigned int>(numErrors));
 
@@ -145,7 +151,8 @@ void backgroundValidate(OperationContext* opCtx,
                                        /*background*/ true,
                                        CollectionValidation::RepairMode::kNone,
                                        &validateResults,
-                                       &output));
+                                       &output,
+                                       /*logDiagnostics=*/false));
     BSONObj obj = output.obj();
 
     ASSERT_EQ(validateResults.valid, valid);
diff --git a/src/mongo/db/catalog/index_consistency.cpp b/src/mongo/db/catalog/index_consistency.cpp
index d38230ea2d1..106781087ac 100644
--- a/src/mongo/db/catalog/index_consistency.cpp
+++ b/src/mongo/db/catalog/index_consistency.cpp
@@ -88,7 +88,7 @@ IndexConsistency::IndexConsistency(OperationContext* opCtx,
 
 void IndexConsistency::addMultikeyMetadataPath(const KeyString::Value& ks, IndexInfo* indexInfo) {
     auto hash = _hashKeyString(ks, indexInfo->indexNameHash);
-    if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+    if (MONGO_unlikely(_validateState->logDiagnostics())) {
         LOGV2(6208500,
               "[validate](multikeyMetadataPath) Adding with the hash",
               "hash"_attr = hash,
@@ -100,7 +100,7 @@ void IndexConsistency::addMultikeyMetadataPath(const KeyString::Value& ks, Index
 void IndexConsistency::removeMultikeyMetadataPath(const KeyString::Value& ks,
                                                   IndexInfo* indexInfo) {
     auto hash = _hashKeyString(ks, indexInfo->indexNameHash);
-    if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+    if (MONGO_unlikely(_validateState->logDiagnostics())) {
         LOGV2(6208501,
               "[validate](multikeyMetadataPath) Removing with the hash",
               "hash"_attr = hash,
@@ -114,9 +114,26 @@ size_t IndexConsistency::getMultikeyMetadataPathCount(IndexInfo* indexInfo) {
 }
 
 bool IndexConsistency::haveEntryMismatch() const {
-    return std::any_of(_indexKeyBuckets.begin(),
-                       _indexKeyBuckets.end(),
-                       [](const IndexKeyBucket& bucket) -> bool { return bucket.indexKeyCount; });
+    bool haveMismatch =
+        std::any_of(_indexKeyBuckets.begin(),
+                    _indexKeyBuckets.end(),
+                    [](const IndexKeyBucket& bucket) -> bool { return bucket.indexKeyCount; });
+
+    if (haveMismatch && _validateState->logDiagnostics()) {
+        for (size_t i = 0; i < _indexKeyBuckets.size(); i++) {
+            if (_indexKeyBuckets[i].indexKeyCount == 0) {
+                continue;
+            }
+
+            LOGV2(7404500,
+                  "[validate](bucket entry mismatch)",
+                  "hash"_attr = i,
+                  "indexKeyCount"_attr = _indexKeyBuckets[i].indexKeyCount,
+                  "bucketBytesSize"_attr = _indexKeyBuckets[i].bucketSizeBytes);
+        }
+    }
+
+    return haveMismatch;
 }
 
 void IndexConsistency::setSecondPhase() {
@@ -273,7 +290,7 @@ void IndexConsistency::addDocKey(OperationContext* opCtx,
         upper.bucketSizeBytes += ks.getSize();
         indexInfo->numRecords++;
 
-        if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+        if (MONGO_unlikely(_validateState->logDiagnostics())) {
             LOGV2(4666602,
                   "[validate](record) Adding with hashes",
                   "hashUpper"_attr = hashUpper,
@@ -327,7 +344,7 @@ void IndexConsistency::addIndexKey(const KeyString::Value& ks,
         upper.bucketSizeBytes += ks.getSize();
         indexInfo->numKeys++;
 
-        if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+        if (MONGO_unlikely(_validateState->logDiagnostics())) {
             LOGV2(4666603,
                   "[validate](index) Adding with hashes",
                   "hashUpper"_attr = hashUpper,
diff --git a/src/mongo/db/catalog/validate_adaptor.cpp b/src/mongo/db/catalog/validate_adaptor.cpp
index 8b2bc6a5edf..cd31d3f36cd 100644
--- a/src/mongo/db/catalog/validate_adaptor.cpp
+++ b/src/mongo/db/catalog/validate_adaptor.cpp
@@ -76,7 +76,7 @@ Status ValidateAdaptor::validateRecord(OperationContext* opCtx,
         return exceptionToStatus();
     }
 
-    if (MONGO_unlikely(_validateState->extraLoggingForTest())) {
+    if (MONGO_unlikely(_validateState->logDiagnostics())) {
         LOGV2(4666601, "[validate]", "recordId"_attr = recordId, "recordData"_attr = recordBson);
     }
 
diff --git a/src/mongo/db/catalog/validate_state.cpp b/src/mongo/db/catalog/validate_state.cpp
index 4fb2eb3d175..81d25a93101 100644
--- a/src/mongo/db/catalog/validate_state.cpp
+++ b/src/mongo/db/catalog/validate_state.cpp
@@ -56,13 +56,13 @@ ValidateState::ValidateState(OperationContext* opCtx,
                              bool background,
                              ValidateOptions options,
                              RepairMode repairMode,
-                             bool turnOnExtraLoggingForTest)
+                             bool logDiagnostics)
     : _nss(nss),
       _background(background),
       _options(options),
       _repairMode(repairMode),
       _dataThrottle(opCtx),
-      _extraLoggingForTest(turnOnExtraLoggingForTest) {
+      _logDiagnostics(logDiagnostics) {
 
     // Subsequent re-locks will use the UUID when 'background' is true.
     if (isBackground()) {
diff --git a/src/mongo/db/catalog/validate_state.h b/src/mongo/db/catalog/validate_state.h
index b9277c71a56..fe6538c778e 100644
--- a/src/mongo/db/catalog/validate_state.h
+++ b/src/mongo/db/catalog/validate_state.h
@@ -55,16 +55,12 @@ 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,
                   RepairMode repairMode,
-                  bool turnOnExtraLoggingForTest = false);
+                  bool logDiagnostics);
 
     const NamespaceString& nss() const {
         return _nss;
@@ -148,11 +144,9 @@ public:
 
     /**
      * Indicates whether extra logging should occur during validation.
-     *
-     * This is for unit testing only. Intended to improve diagnosibility.
      */
-    bool extraLoggingForTest() {
-        return _extraLoggingForTest;
+    bool logDiagnostics() {
+        return _logDiagnostics;
     }
 
     boost::optional<Timestamp> getValidateTimestamp() {
@@ -229,8 +223,8 @@ 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;
+    // Can be set to obtain better insight into what validate sees/does.
+    bool _logDiagnostics;
 
     boost::optional<Timestamp> _validateTs = boost::none;
 };
diff --git a/src/mongo/db/catalog/validate_state_test.cpp b/src/mongo/db/catalog/validate_state_test.cpp
index da04712986f..57b6c891e98 100644
--- a/src/mongo/db/catalog/validate_state_test.cpp
+++ b/src/mongo/db/catalog/validate_state_test.cpp
@@ -121,7 +121,8 @@ TEST_F(ValidateStateTest, NonExistentCollectionShouldThrowNamespaceNotFoundError
                            kNss,
                            /*background*/ false,
                            CollectionValidation::ValidateOptions::kNoFullValidation,
-                           CollectionValidation::RepairMode::kNone),
+                           CollectionValidation::RepairMode::kNone,
+                           /*logDiagnostics=*/false),
                        AssertionException,
                        ErrorCodes::NamespaceNotFound);
 
@@ -130,7 +131,8 @@ TEST_F(ValidateStateTest, NonExistentCollectionShouldThrowNamespaceNotFoundError
                            kNss,
                            /*background*/ true,
                            CollectionValidation::ValidateOptions::kNoFullValidation,
-                           CollectionValidation::RepairMode::kNone),
+                           CollectionValidation::RepairMode::kNone,
+                           /*logDiagnostics=*/false),
                        AssertionException,
                        ErrorCodes::NamespaceNotFound);
 }
@@ -150,7 +152,8 @@ TEST_F(ValidateStateTest, UncheckpointedCollectionShouldBeAbleToInitializeCursor
         kNss,
         /*background*/ true,
         CollectionValidation::ValidateOptions::kNoFullValidation,
-        CollectionValidation::RepairMode::kNone);
+        CollectionValidation::RepairMode::kNone,
+        /*logDiagnostics=*/false);
     // Assert that cursors are able to created on the new collection.
     validateState.initializeCursors(opCtx);
     // There should only be a first record id if cursors were initialized successfully.
@@ -188,7 +191,8 @@ TEST_F(ValidateStateTest, OpenCursorsOnAllIndexes) {
             kNss,
             /*background*/ false,
             CollectionValidation::ValidateOptions::kNoFullValidation,
-            CollectionValidation::RepairMode::kNone);
+            CollectionValidation::RepairMode::kNone,
+            /*logDiagnostics=*/false);
         validateState.initializeCursors(opCtx);
 
         // Make sure all of the indexes were found and cursors opened against them. Including the
@@ -207,7 +211,8 @@ TEST_F(ValidateStateTest, OpenCursorsOnAllIndexes) {
         kNss,
         /*background*/ false,
         CollectionValidation::ValidateOptions::kNoFullValidation,
-        CollectionValidation::RepairMode::kNone);
+        CollectionValidation::RepairMode::kNone,
+        /*logDiagnostics=*/false);
     validateState.initializeCursors(opCtx);
     ASSERT_EQ(validateState.getIndexes().size(), 5);
 }
@@ -246,7 +251,8 @@ TEST_F(ValidateStateTest, OpenCursorsOnAllIndexesWithBackground) {
         kNss,
         /*background*/ true,
         CollectionValidation::ValidateOptions::kNoFullValidation,
-        CollectionValidation::RepairMode::kNone);
+        CollectionValidation::RepairMode::kNone,
+        /*logDiagnostics=*/false);
     validateState.initializeCursors(opCtx);
 
     // We should be able to open a cursor on each index.
@@ -295,7 +301,8 @@ TEST_F(ValidateStateTest, CursorsAreNotOpenedAgainstCheckpointedIndexesThatWereL
             kNss,
             /*background*/ true,
             CollectionValidation::ValidateOptions::kNoFullValidation,
-            CollectionValidation::RepairMode::kNone);
+            CollectionValidation::RepairMode::kNone,
+            /*logDiagnostics=*/false);
         validateState.initializeCursors(opCtx);
         ASSERT_EQ(validateState.getIndexes().size(), 3);
     }
@@ -309,7 +316,8 @@ TEST_F(ValidateStateTest, CursorsAreNotOpenedAgainstCheckpointedIndexesThatWereL
         kNss,
         /*background*/ true,
         CollectionValidation::ValidateOptions::kNoFullValidation,
-        CollectionValidation::RepairMode::kNone);
+        CollectionValidation::RepairMode::kNone,
+        /*logDiagnostics=*/false);
     validateState.initializeCursors(opCtx);
     ASSERT_EQ(validateState.getIndexes().size(), 3);
 }
diff --git a/src/mongo/db/commands/validate.cpp b/src/mongo/db/commands/validate.cpp
index cda82da19fb..2f298a0c67d 100644
--- a/src/mongo/db/commands/validate.cpp
+++ b/src/mongo/db/commands/validate.cpp
@@ -123,6 +123,7 @@ public:
 
         const NamespaceString nss(CommandHelpers::parseNsCollectionRequired(dbname, cmdObj));
         bool background = cmdObj["background"].trueValue();
+        bool logDiagnostics = cmdObj["logDiagnostics"].trueValue();
 
         // Background validation is not supported on the ephemeralForTest storage engine due to its
         // lack of support for timestamps. Switch the mode to foreground validation instead.
@@ -180,7 +181,7 @@ public:
         auto repairMode = CollectionValidation::RepairMode::kNone;
         ValidateResults validateResults;
         Status status = CollectionValidation::validate(
-            opCtx, nss, options, background, repairMode, &validateResults, &result);
+            opCtx, nss, options, background, repairMode, &validateResults, &result, logDiagnostics);
         if (!status.isOK()) {
             return CommandHelpers::appendCommandStatusNoThrow(result, status);
         }
diff --git a/src/mongo/db/repair_database.cpp b/src/mongo/db/repair_database.cpp
index ed5158d016e..0acc3194f2d 100644
--- a/src/mongo/db/repair_database.cpp
+++ b/src/mongo/db/repair_database.cpp
@@ -174,7 +174,8 @@ Status repairCollections(OperationContext* opCtx,
                                                 background,
                                                 CollectionValidation::RepairMode::kRepair,
                                                 &validateResults,
-                                                &output);
+                                                &output,
+                                                /*logDiagnostics=*/false);
         if (!status.isOK()) {
             return status;
         }
diff --git a/src/mongo/db/repl/idempotency_test_fixture.cpp b/src/mongo/db/repl/idempotency_test_fixture.cpp
index cbe3b235373..7c2cc6e6a1f 100644
--- a/src/mongo/db/repl/idempotency_test_fixture.cpp
+++ b/src/mongo/db/repl/idempotency_test_fixture.cpp
@@ -410,7 +410,8 @@ CollectionState IdempotencyTest::validate(const NamespaceString& nss) {
                                            false,
                                            CollectionValidation::RepairMode::kNone,
                                            &validateResults,
-                                           &bob));
+                                           &bob,
+                                           /*logDiagnostics=*/false));
         ASSERT_TRUE(validateResults.valid);
     }
 
diff --git a/src/mongo/dbtests/validate_tests.cpp b/src/mongo/dbtests/validate_tests.cpp
index 627a97e4398..82285e9370a 100644
--- a/src/mongo/dbtests/validate_tests.cpp
+++ b/src/mongo/dbtests/validate_tests.cpp
@@ -51,7 +51,7 @@ using std::unique_ptr;
 namespace {
 
 const auto kIndexVersion = IndexDescriptor::IndexVersion::kV2;
-const bool kTurnOnExtraLoggingForTest = true;
+const bool kLogDiagnostics = true;
 
 }  // namespace
 
@@ -110,14 +110,8 @@ protected:
         ValidateResults results;
         BSONObjBuilder output;
 
-        ASSERT_OK(CollectionValidation::validate(&_opCtx,
-                                                 _nss,
-                                                 options,
-                                                 _background,
-                                                 repairMode,
-                                                 &results,
-                                                 &output,
-                                                 kTurnOnExtraLoggingForTest));
+        ASSERT_OK(CollectionValidation::validate(
+            &_opCtx, _nss, options, _background, repairMode, &results, &output, kLogDiagnostics));
 
         //  Check if errors are reported if and only if valid is set to false.
         ASSERT_EQ(results.valid, results.errors.empty());
@@ -1221,7 +1215,7 @@ public:
                 CollectionValidation::RepairMode::kNone,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1344,7 +1338,7 @@ public:
                 CollectionValidation::RepairMode::kNone,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1444,7 +1438,7 @@ public:
                 CollectionValidation::RepairMode::kNone,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1913,7 +1907,7 @@ public:
                 CollectionValidation::RepairMode::kNone,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1943,7 +1937,7 @@ public:
                 CollectionValidation::RepairMode::kRepair,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -1974,7 +1968,7 @@ public:
                 CollectionValidation::RepairMode::kRepair,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -2114,7 +2108,7 @@ public:
                 CollectionValidation::RepairMode::kNone,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -2144,7 +2138,7 @@ public:
                 CollectionValidation::RepairMode::kRepair,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);
@@ -2174,7 +2168,7 @@ public:
                 CollectionValidation::RepairMode::kNone,
                 &results,
                 &output,
-                kTurnOnExtraLoggingForTest));
+                kLogDiagnostics));
 
             auto dumpOnErrorGuard = makeGuard([&] {
                 StorageDebugUtil::printValidateResults(results);