diff options
author | Dianna Hohensee <dianna.hohensee@mongodb.com> | 2020-03-05 19:01:26 -0500 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2020-03-13 15:10:49 +0000 |
commit | 33076ddc839fda1e5c5dec91d616e56c2e9d40ab (patch) | |
tree | 3304ba23c72604d17d051c329d63a30d2ecc3d1d | |
parent | d1b708e595e46846b76aa3172b36278848939700 (diff) | |
download | mongo-33076ddc839fda1e5c5dec91d616e56c2e9d40ab.tar.gz |
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%)
(cherry picked from commit 86d40fda4d156c0a439f1c5edb2b7890a085d337)
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%)
-rw-r--r-- | src/mongo/db/catalog/SConscript | 1 | ||||
-rw-r--r-- | src/mongo/db/catalog/collection_validation.cpp | 5 | ||||
-rw-r--r-- | src/mongo/db/catalog/collection_validation.h | 3 | ||||
-rw-r--r-- | src/mongo/db/catalog/index_consistency.cpp | 20 | ||||
-rw-r--r-- | src/mongo/db/catalog/validate_adaptor.cpp | 7 | ||||
-rw-r--r-- | src/mongo/db/catalog/validate_state.cpp | 9 | ||||
-rw-r--r-- | src/mongo/db/catalog/validate_state.h | 19 | ||||
-rw-r--r-- | src/mongo/db/storage/SConscript | 4 | ||||
-rw-r--r-- | src/mongo/db/storage/storage_debug_util.cpp (renamed from src/mongo/db/storage/storage_unittest_debug_util.cpp) | 67 | ||||
-rw-r--r-- | src/mongo/db/storage/storage_debug_util.h (renamed from src/mongo/db/storage/storage_unittest_debug_util.h) | 16 | ||||
-rw-r--r-- | src/mongo/dbtests/SConscript | 2 | ||||
-rw-r--r-- | src/mongo/dbtests/validate_tests.cpp | 18 |
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); |