diff options
Diffstat (limited to 'src')
-rw-r--r-- | src/mongo/db/commands/parameters.cpp | 9 | ||||
-rw-r--r-- | src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp | 10 | ||||
-rw-r--r-- | src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp | 177 | ||||
-rw-r--r-- | src/mongo/db/storage/wiredtiger/wiredtiger_util.h | 6 | ||||
-rw-r--r-- | src/mongo/db/storage/wiredtiger/wiredtiger_util_test.cpp | 84 | ||||
-rw-r--r-- | src/mongo/logv2/log_component.h | 15 |
6 files changed, 280 insertions, 21 deletions
diff --git a/src/mongo/db/commands/parameters.cpp b/src/mongo/db/commands/parameters.cpp index ce7d69ea7b2..5a7840e655f 100644 --- a/src/mongo/db/commands/parameters.cpp +++ b/src/mongo/db/commands/parameters.cpp @@ -343,6 +343,15 @@ public: return false; } + // WiredTiger component verbosity levels cannot be changed at runtime. + if (parameterName == "logComponentVerbosity") { + const BSONObj obj = parameter.Obj(); + if (obj.hasField("storage") && obj.getObjectField("storage").hasField("wt")) { + errmsg = "Cannot set log component verbosity parameter storage.wt at runtime."; + return false; + } + } + if (parameterName == "requireApiVersion" && parameter.trueValue() && (serverGlobalParams.clusterRole == ClusterRole::ConfigServer || serverGlobalParams.clusterRole == ClusterRole::ShardServer)) { diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp index 317e8cf5409..ca3c6c49bf0 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp @@ -401,11 +401,11 @@ WiredTigerKVEngine::WiredTigerKVEngine(const std::string& canonicalName, << ",close_handle_minimum=" << gWiredTigerFileHandleCloseMinimum << "),"; ss << "statistics_log=(wait=" << wiredTigerGlobalOptions.statisticsLogDelaySecs << "),"; - if (shouldLog(::mongo::logv2::LogComponent::kStorageRecovery, logv2::LogSeverity::Debug(3))) { - ss << "verbose=[recovery_progress,checkpoint_progress,compact_progress,recovery],"; - } else { - ss << "verbose=[recovery_progress,checkpoint_progress,compact_progress],"; - } + // Enable JSON output for errors and messages. + ss << "json_output=(error,message),"; + + // Generate the settings related to the verbose configuration. + ss << WiredTigerUtil::generateWTVerboseConfiguration() << ","; if (kDebugBuild) { // Do not abort the process when corruption is found in debug builds, which supports diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp index 5f560b6fc5b..20b44aa710b 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp @@ -27,7 +27,7 @@ * it in the license file. */ -#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kStorage +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kWiredTiger #include "mongo/platform/basic.h" @@ -52,6 +52,7 @@ #include "mongo/util/fail_point.h" #include "mongo/util/processinfo.h" #include "mongo/util/scopeguard.h" +#include "mongo/util/static_immortal.h" #include "mongo/util/str.h" #include "mongo/util/testing_proctor.h" @@ -525,7 +526,103 @@ size_t WiredTigerUtil::getCacheSizeMB(double requestedCacheSizeGB) { return static_cast<size_t>(cacheSizeMB); } +logv2::LogSeverity getWTLOGV2SeverityLevel(const BSONObj& obj) { + const std::string field = "verbose_level_id"; + + if (!obj.hasField(field)) { + throw std::logic_error("The following field is missing: " + field); + } + + BSONElement verbose_level_id_ele = obj[field]; + if (!verbose_level_id_ele.isNumber()) { + throw std::logic_error("The value associated to " + field + " must be a number"); + } + + // Matching each WiredTiger verbosity level to the equivalent LOGV2 severity level. + switch (verbose_level_id_ele.Int()) { + case WT_VERBOSE_ERROR: + return logv2::LogSeverity::Error(); + case WT_VERBOSE_WARNING: + return logv2::LogSeverity::Warning(); + case WT_VERBOSE_NOTICE: + return logv2::LogSeverity::Info(); + case WT_VERBOSE_INFO: + return logv2::LogSeverity::Log(); + case WT_VERBOSE_DEBUG: + return logv2::LogSeverity::Debug(1); + default: + return logv2::LogSeverity::Log(); + } +} + +logv2::LogComponent getWTLOGV2Component(const BSONObj& obj) { + const std::string field = "category_id"; + + if (!obj.hasField(field)) { + throw std::logic_error("The following field is missing: " + field); + } + + BSONElement category_id_ele = obj[field]; + if (!category_id_ele.isNumber()) { + throw std::logic_error("The value associated to " + field + " must be a number"); + } + + switch (category_id_ele.Int()) { + case WT_VERB_BACKUP: + return logv2::LogComponent::kWiredTigerBackup; + case WT_VERB_CHECKPOINT: + case WT_VERB_CHECKPOINT_CLEANUP: + case WT_VERB_CHECKPOINT_PROGRESS: + return logv2::LogComponent::kWiredTigerCheckpoint; + case WT_VERB_COMPACT: + case WT_VERB_COMPACT_PROGRESS: + return logv2::LogComponent::kWiredTigerCompact; + case WT_VERB_EVICT: + return logv2::LogComponent::kWiredTigerEviction; + case WT_VERB_HS: + case WT_VERB_HS_ACTIVITY: + return logv2::LogComponent::kWiredTigerHS; + case WT_VERB_RECOVERY: + case WT_VERB_RECOVERY_PROGRESS: + return logv2::LogComponent::kWiredTigerRecovery; + case WT_VERB_RTS: + return logv2::LogComponent::kWiredTigerRTS; + case WT_VERB_SALVAGE: + return logv2::LogComponent::kWiredTigerSalvage; + case WT_VERB_TIERED: + return logv2::LogComponent::kWiredTigerTiered; + case WT_VERB_TIMESTAMP: + return logv2::LogComponent::kWiredTigerTimestamp; + case WT_VERB_TRANSACTION: + return logv2::LogComponent::kWiredTigerTransaction; + case WT_VERB_VERIFY: + return logv2::LogComponent::kWiredTigerVerify; + case WT_VERB_LOG: + return logv2::LogComponent::kWiredTigerWriteLog; + default: + return logv2::LogComponent::kWiredTiger; + } +} + namespace { + +void logWTErrorMessage(int id, int errorCode, const std::string& message) { + logv2::LogComponent component = logv2::LogComponent::kWiredTiger; + logv2::DynamicAttributes attr; + attr.add("error", errorCode); + + try { + // Parse the WT JSON message string. + BSONObj obj = fromjson(message); + attr.add("message", obj); + component = getWTLOGV2Component(obj); + } catch (...) { + // Fall back to default behaviour. + attr.add("message", message); + } + LOGV2_ERROR_OPTIONS(id, logv2::LogOptions{component}, "WiredTiger error message", attr); +} + int mdb_handle_error_with_startup_suppression(WT_EVENT_HANDLER* handler, WT_SESSION* session, int errorCode, @@ -551,11 +648,8 @@ int mdb_handle_error_with_startup_suppression(WT_EVENT_HANDLER* handler, return 0; } } - LOGV2_ERROR(22435, - "WiredTiger error ({error}) {message}", - "WiredTiger error", - "error"_attr = errorCode, - "message"_attr = message); + + logWTErrorMessage(22435, errorCode, message); // Don't abort on WT_PANIC when repairing, as the error will be handled at a higher layer. if (storageGlobalParams.repair) { @@ -573,11 +667,7 @@ int mdb_handle_error(WT_EVENT_HANDLER* handler, int errorCode, const char* message) { try { - LOGV2_ERROR(22436, - "WiredTiger error ({errorCode}) {message}", - "WiredTiger error", - "error"_attr = errorCode, - "message"_attr = redact(message)); + logWTErrorMessage(22436, errorCode, std::string(redact(message))); // Don't abort on WT_PANIC when repairing, as the error will be handled at a higher layer. if (storageGlobalParams.repair) { @@ -591,8 +681,23 @@ int mdb_handle_error(WT_EVENT_HANDLER* handler, } int mdb_handle_message(WT_EVENT_HANDLER* handler, WT_SESSION* session, const char* message) { + logv2::DynamicAttributes attr; + logv2::LogSeverity severity = ::mongo::logv2::LogSeverity::Log(); + logv2::LogOptions options = ::mongo::logv2::LogOptions{MongoLogV2DefaultComponent_component}; + try { - LOGV2(22430, "WiredTiger message", "message"_attr = redact(message)); + try { + // Parse the WT JSON message string. + const BSONObj obj = fromjson(message); + severity = getWTLOGV2SeverityLevel(obj); + options = logv2::LogOptions{getWTLOGV2Component(obj)}; + attr.add("message", redact(obj)); + } catch (...) { + // Fall back to default behaviour. + attr.add("message", redact(message)); + } + + LOGV2_IMPL(22430, severity, options, "WiredTiger message", attr); } catch (...) { std::terminate(); } @@ -1049,4 +1154,52 @@ void WiredTigerUtil::appendSnapshotWindowSettings(WiredTigerKVEngine* engine, settings.append("min pinned timestamp", minPinned); } +std::string WiredTigerUtil::generateWTVerboseConfiguration() { + // Mapping between LOGV2 WiredTiger components and their WiredTiger verbose setting counterpart. + static const StaticImmortal wtVerboseComponents = std::map<logv2::LogComponent, std::string>{ + {logv2::LogComponent::kWiredTigerBackup, "backup"}, + {logv2::LogComponent::kWiredTigerCheckpoint, "checkpoint"}, + {logv2::LogComponent::kWiredTigerCompact, "compact"}, + {logv2::LogComponent::kWiredTigerEviction, "evict"}, + {logv2::LogComponent::kWiredTigerHS, "history_store"}, + {logv2::LogComponent::kWiredTigerRecovery, "recovery"}, + {logv2::LogComponent::kWiredTigerRTS, "rts"}, + {logv2::LogComponent::kWiredTigerSalvage, "salvage"}, + {logv2::LogComponent::kWiredTigerTiered, "tiered"}, + {logv2::LogComponent::kWiredTigerTimestamp, "timestamp"}, + {logv2::LogComponent::kWiredTigerTransaction, "transaction"}, + {logv2::LogComponent::kWiredTigerVerify, "verify"}, + {logv2::LogComponent::kWiredTigerWriteLog, "log"}, + }; + + str::stream cfg; + + // Define the verbose level for each component. + cfg << "verbose=["; + + // Enable WiredTiger progress messages. + cfg << "recovery_progress:1,checkpoint_progress:1,compact_progress:1"; + + // Process each LOGV2 WiredTiger component and set the desired verbosity level. + for (const auto& [component, componentStr] : *wtVerboseComponents) { + auto severity = + logv2::LogManager::global().getGlobalSettings().getMinimumLogSeverity(component); + + cfg << ","; + + int level; + if (severity.toInt() >= logv2::LogSeverity::Debug(1).toInt()) + level = WT_VERBOSE_DEBUG; + else + level = WT_VERBOSE_INFO; + + cfg << componentStr << ":" << level; + } + + cfg << "]"; + + return cfg; +} + + } // namespace mongo diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h index b2dbc5f3ffd..c716ea0cc56 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h @@ -306,6 +306,12 @@ public: static Status setTableLogging(WT_SESSION* session, const std::string& uri, bool on); /** + * Generates a WiredTiger connection configuration given the LOGV2 WiredTiger components + * verbosity levels. + */ + static std::string generateWTVerboseConfiguration(); + + /** * Casts unsigned 64-bit statistics value to T. * If original value exceeds maximum value of T, return max(T). */ diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util_test.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_util_test.cpp index 4decabddcba..106bce21c87 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_util_test.cpp +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util_test.cpp @@ -27,6 +27,8 @@ * it in the license file. */ +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kStorage + #include "mongo/platform/basic.h" #include <sstream> @@ -49,13 +51,16 @@ using std::stringstream; class WiredTigerConnection { public: - WiredTigerConnection(StringData dbpath, StringData extraStrings) : _conn(nullptr) { + WiredTigerConnection(StringData dbpath, + StringData extraStrings, + WT_EVENT_HANDLER* eventHandler = nullptr) + : _conn(nullptr) { std::stringstream ss; ss << "create,"; ss << extraStrings; string config = ss.str(); _fastClockSource = std::make_unique<SystemClockSource>(); - int ret = wiredtiger_open(dbpath.toString().c_str(), nullptr, config.c_str(), &_conn); + int ret = wiredtiger_open(dbpath.toString().c_str(), eventHandler, config.c_str(), &_conn); ASSERT_OK(wtRCToStatus(ret)); ASSERT(_conn); } @@ -76,9 +81,12 @@ private: class WiredTigerUtilHarnessHelper { public: - WiredTigerUtilHarnessHelper(StringData extraStrings) + explicit WiredTigerUtilHarnessHelper(StringData extraStrings, + WiredTigerEventHandler* eventHandler = nullptr) : _dbpath("wt_test"), - _connection(_dbpath.path(), extraStrings), + _connection(_dbpath.path(), + extraStrings, + eventHandler == nullptr ? nullptr : eventHandler->getWtEventHandler()), _sessionCache(_connection.getConnection(), _connection.getClockSource()) {} @@ -348,4 +356,72 @@ TEST(WiredTigerUtilTest, GetStatisticsValueValidKey) { ASSERT_EQUALS(0U, result.getValue()); } +TEST(WiredTigerUtilTest, ParseAPIMessages) { + // Custom event handler. + WiredTigerEventHandler eventHandler; + + // Define a WiredTiger connection configuration that enables JSON encoding for all messages + // related to the WT_VERB_API category. + const std::string connection_cfg = "json_output=[error,message],verbose=[api]"; + + // Initialize WiredTiger. + WiredTigerUtilHarnessHelper harnessHelper(connection_cfg.c_str(), &eventHandler); + + // Create a session. + WiredTigerRecoveryUnit recoveryUnit(harnessHelper.getSessionCache(), + harnessHelper.getOplogManager()); + WT_SESSION* wtSession = recoveryUnit.getSession()->getSession(); + + // Perform simple WiredTiger operations while capturing the generated logs. + startCapturingLogMessages(); + ASSERT_OK(wtRCToStatus(wtSession->create(wtSession, "table:ev_api", nullptr))); + stopCapturingLogMessages(); + + // Verify there is at least one message from WiredTiger and their content. + bool foundWTMessage = false; + for (auto&& bson : getCapturedBSONFormatLogMessages()) { + if (bson["c"].String() == "WT") { + foundWTMessage = true; + ASSERT_EQUALS(bson["attr"]["message"]["category"].String(), "WT_VERB_API"); + ASSERT_EQUALS(bson["attr"]["message"]["category_id"].Int(), WT_VERB_API); + } + } + ASSERT_TRUE(foundWTMessage); +} + +TEST(WiredTigerUtilTest, ParseCompactMessages) { + // Custom event handler. + WiredTigerEventHandler eventHandler; + + // Define a WiredTiger connection configuration that enables JSON encoding for all messages + // related to the WT_VERB_COMPACT category. + const std::string connection_cfg = "json_output=[error,message],verbose=[compact]"; + + // Initialize WiredTiger. + WiredTigerUtilHarnessHelper harnessHelper(connection_cfg.c_str(), &eventHandler); + + // Create a session. + WT_SESSION* wtSession; + ASSERT_OK(wtRCToStatus(harnessHelper.getSessionCache()->conn()->open_session( + harnessHelper.getSessionCache()->conn(), nullptr, nullptr, &wtSession))); + + // Perform simple WiredTiger operations while capturing the generated logs. + const std::string uri = "table:ev_compact"; + startCapturingLogMessages(); + ASSERT_OK(wtRCToStatus(wtSession->create(wtSession, uri.c_str(), nullptr))); + ASSERT_OK(wtRCToStatus(wtSession->compact(wtSession, uri.c_str(), nullptr))); + stopCapturingLogMessages(); + + // Verify there is at least one message from WiredTiger and their content. + bool foundWTMessage = false; + for (auto&& bson : getCapturedBSONFormatLogMessages()) { + if (bson["c"].String() == "WTCMPCT") { + foundWTMessage = true; + ASSERT_EQUALS(bson["attr"]["message"]["category"].String(), "WT_VERB_COMPACT"); + ASSERT_EQUALS(bson["attr"]["message"]["category_id"].Int(), WT_VERB_COMPACT); + } + } + ASSERT_TRUE(foundWTMessage); +} + } // namespace mongo diff --git a/src/mongo/logv2/log_component.h b/src/mongo/logv2/log_component.h index 22d18d0540c..2b1985756b9 100644 --- a/src/mongo/logv2/log_component.h +++ b/src/mongo/logv2/log_component.h @@ -33,6 +33,7 @@ #include <string> #include "mongo/base/string_data.h" +#include "mongo/config.h" namespace mongo::logv2 { @@ -74,6 +75,20 @@ namespace mongo::logv2 { X(kStorage, , "storage" , "STORAGE" , kDefault) \ X(kStorageRecovery, , "recovery" , "RECOVERY", kStorage) \ X(kJournal, , "journal" , "JOURNAL" , kStorage) \ + X(kWiredTiger, , "wt" , "WT" , kStorage) \ + X(kWiredTigerBackup, , "wtBackup" , "WTBACKUP", kWiredTiger) \ + X(kWiredTigerCheckpoint, , "wtCheckpoint" , "WTCHKPT" , kWiredTiger) \ + X(kWiredTigerCompact, , "wtCompact" , "WTCMPCT" , kWiredTiger) \ + X(kWiredTigerEviction, , "wtEviction" , "WTEVICT" , kWiredTiger) \ + X(kWiredTigerHS, , "wtHS" , "WTHS" , kWiredTiger) \ + X(kWiredTigerRecovery, , "wtRecovery" , "WTRECOV" , kWiredTiger) \ + X(kWiredTigerRTS, , "wtRTS" , "WTRTS" , kWiredTiger) \ + X(kWiredTigerSalvage, , "wtSalvage" , "WTSLVG" , kWiredTiger) \ + X(kWiredTigerTiered, , "wtTiered" , "WTTIER" , kWiredTiger) \ + X(kWiredTigerTimestamp, , "wtTimestamp" , "WTTS" , kWiredTiger) \ + X(kWiredTigerTransaction, , "wtTransaction" , "WTTXN" , kWiredTiger) \ + X(kWiredTigerVerify, , "wtVerify" , "WTVRFY" , kWiredTiger) \ + X(kWiredTigerWriteLog, , "wtWriteLog" , "WTWRTLOG", kWiredTiger) \ X(kWrite, , "write" , "WRITE" , kDefault) \ X(kFTDC, , "ftdc" , "FTDC" , kDefault) \ X(kASIO, , "asio" , "ASIO" , kNetwork) \ |