diff options
author | babenko <babenko@yandex-team.com> | 2024-10-20 17:04:47 +0300 |
---|---|---|
committer | babenko <babenko@yandex-team.com> | 2024-10-20 17:19:01 +0300 |
commit | e36aa48cf1a20abbfa2a921748f3f1a32b7000be (patch) | |
tree | 834cd5cfd04a4c8a80ea24626fa280f420ae5126 /yt | |
parent | 849246505c7f71dc743ab87a18a4d9a8da1cd1bf (diff) | |
download | ydb-e36aa48cf1a20abbfa2a921748f3f1a32b7000be.tar.gz |
Introduce message_level_overrides to tune log message levels at runtime
* Changelog entry
Type: feature
Add message_level_overrides option to logging config for better run-time tuning.
commit_hash:07e9563fd111c437edf7ac0e5dd190781878d8fa
Diffstat (limited to 'yt')
-rw-r--r-- | yt/cpp/mapreduce/interface/logging/yt_log.cpp | 2 | ||||
-rw-r--r-- | yt/yt/core/logging/config.cpp | 20 | ||||
-rw-r--r-- | yt/yt/core/logging/config.h | 10 | ||||
-rw-r--r-- | yt/yt/core/logging/log_manager.cpp | 50 | ||||
-rw-r--r-- | yt/yt/core/logging/unittests/logging_ut.cpp | 209 |
5 files changed, 196 insertions, 95 deletions
diff --git a/yt/cpp/mapreduce/interface/logging/yt_log.cpp b/yt/cpp/mapreduce/interface/logging/yt_log.cpp index 6b1e8ff049..4ff38d4c58 100644 --- a/yt/cpp/mapreduce/interface/logging/yt_log.cpp +++ b/yt/cpp/mapreduce/interface/logging/yt_log.cpp @@ -30,8 +30,6 @@ public: return; } - anchor->Enabled.store(true); - auto guard = Guard(Mutex_); anchor->SourceLocation = sourceLocation; anchor->AnchorMessage = anchorMessage; diff --git a/yt/yt/core/logging/config.cpp b/yt/yt/core/logging/config.cpp index 4acde166a9..4fc2823945 100644 --- a/yt/yt/core/logging/config.cpp +++ b/yt/yt/core/logging/config.cpp @@ -196,13 +196,16 @@ void TLogManagerConfig::Register(TRegistrar registrar) registrar.Parameter("shutdown_busy_timeout", &TThis::ShutdownGraceTimeout) .Default(TDuration::Zero()); - registrar.Parameter("writers", &TThis::Writers); registrar.Parameter("rules", &TThis::Rules); - registrar.Parameter("suppressed_messages", &TThis::SuppressedMessages) - .Default(); + registrar.Parameter("writers", &TThis::Writers); registrar.Parameter("category_rate_limits", &TThis::CategoryRateLimits) .Default(); + registrar.Parameter("suppressed_messages", &TThis::SuppressedMessages) + .Optional(); + registrar.Parameter("message_level_overrides", &TThis::MessageLevelOverrides) + .Optional(); + registrar.Parameter("request_suppression_timeout", &TThis::RequestSuppressionTimeout) .Alias("trace_suppression_timeout") .Default(TDuration::Zero()); @@ -235,8 +238,12 @@ TLogManagerConfigPtr TLogManagerConfig::ApplyDynamic(const TLogManagerDynamicCon mergedConfig->ShutdownGraceTimeout = ShutdownGraceTimeout; mergedConfig->Rules = CloneYsonStructs(dynamicConfig->Rules.value_or(Rules)); mergedConfig->Writers = CloneYsonStructs(Writers); - mergedConfig->SuppressedMessages = dynamicConfig->SuppressedMessages.value_or(SuppressedMessages); mergedConfig->CategoryRateLimits = dynamicConfig->CategoryRateLimits.value_or(CategoryRateLimits); + mergedConfig->SuppressedMessages = dynamicConfig->SuppressedMessages.value_or(SuppressedMessages); + mergedConfig->MessageLevelOverrides = MessageLevelOverrides; + for (const auto& [message, level] : dynamicConfig->MessageLevelOverrides) { + mergedConfig->MessageLevelOverrides[message] = level; + } mergedConfig->RequestSuppressionTimeout = dynamicConfig->RequestSuppressionTimeout.value_or(RequestSuppressionTimeout); mergedConfig->EnableAnchorProfiling = dynamicConfig->EnableAnchorProfiling.value_or(EnableAnchorProfiling); mergedConfig->MinLoggedMessageRateToProfile = dynamicConfig->MinLoggedMessageRateToProfile.value_or(MinLoggedMessageRateToProfile); @@ -459,9 +466,12 @@ void TLogManagerDynamicConfig::Register(TRegistrar registrar) registrar.Parameter("rules", &TThis::Rules) .Optional(); + registrar.Parameter("category_rate_limits", &TThis::CategoryRateLimits) + .Optional(); + registrar.Parameter("suppressed_messages", &TThis::SuppressedMessages) .Optional(); - registrar.Parameter("category_rate_limits", &TThis::CategoryRateLimits) + registrar.Parameter("message_level_overrides", &TThis::MessageLevelOverrides) .Optional(); registrar.Parameter("request_suppression_timeout", &TThis::RequestSuppressionTimeout) diff --git a/yt/yt/core/logging/config.h b/yt/yt/core/logging/config.h index 6e5f2b0f9f..f025e58f11 100644 --- a/yt/yt/core/logging/config.h +++ b/yt/yt/core/logging/config.h @@ -160,9 +160,13 @@ public: std::vector<TRuleConfigPtr> Rules; THashMap<TString, NYTree::IMapNodePtr> Writers; - std::vector<TString> SuppressedMessages; THashMap<TString, i64> CategoryRateLimits; + //! Messages with these prefixes will not be logged regardless of the configured levels. + std::vector<TString> SuppressedMessages; + //! Overrides levels of messages with a matching prefix . + THashMap<TString, ELogLevel> MessageLevelOverrides; + TDuration RequestSuppressionTimeout; bool EnableAnchorProfiling; @@ -215,9 +219,11 @@ public: std::optional<int> LowBacklogWatermark; std::optional<std::vector<TRuleConfigPtr>> Rules; - std::optional<std::vector<TString>> SuppressedMessages; std::optional<THashMap<TString, i64>> CategoryRateLimits; + std::optional<std::vector<TString>> SuppressedMessages; + THashMap<TString, ELogLevel> MessageLevelOverrides; + std::optional<TDuration> RequestSuppressionTimeout; std::optional<bool> EnableAnchorProfiling; diff --git a/yt/yt/core/logging/log_manager.cpp b/yt/yt/core/logging/log_manager.cpp index 1a6d51cb02..d7e15992be 100644 --- a/yt/yt/core/logging/log_manager.cpp +++ b/yt/yt/core/logging/log_manager.cpp @@ -511,29 +511,24 @@ public: { auto guard = Guard(SpinLock_); auto config = Config_.Acquire(); - - bool enabled = true; - for (const auto& prefix : config->SuppressedMessages) { - if (anchor->AnchorMessage.StartsWith(prefix)) { - enabled = false; - break; - } - } - - anchor->Enabled.store(enabled, std::memory_order::relaxed); - anchor->CurrentVersion.store(GetVersion(), std::memory_order::relaxed); + DoUpdateAnchor(config, anchor); } - void RegisterStaticAnchor(TLoggingAnchor* anchor, ::TSourceLocation sourceLocation, TStringBuf message) + void RegisterStaticAnchor( + TLoggingAnchor* anchor, + ::TSourceLocation sourceLocation, + TStringBuf message) { if (anchor->Registered.exchange(true)) { return; } auto guard = Guard(SpinLock_); + auto config = Config_.Acquire(); anchor->SourceLocation = sourceLocation; anchor->AnchorMessage = BuildAnchorMessage(sourceLocation, message); DoRegisterAnchor(anchor); + DoUpdateAnchor(config, anchor); } TLoggingAnchor* RegisterDynamicAnchor(TString anchorMessage) @@ -1356,9 +1351,7 @@ private: return eventsWritten; } - void DoUpdateCategory( - const TLogManagerConfigPtr& config, - TLoggingCategory* category) + void DoUpdateCategory(const TLogManagerConfigPtr& config, TLoggingCategory* category) { VERIFY_THREAD_AFFINITY_ANY(); @@ -1384,6 +1377,33 @@ private: FirstAnchor_.store(anchor); } + void DoUpdateAnchor(const TLogManagerConfigPtr& config, TLoggingAnchor* anchor) + { + VERIFY_SPINLOCK_AFFINITY(SpinLock_); + + auto isPrefixOf = [] (const TString& message, const std::vector<TString>& prefixes) { + for (const auto& prefix : prefixes) { + if (message.StartsWith(prefix)) { + return true; + } + } + return false; + }; + + auto findByPrefix = [] (const TString& message, const THashMap<TString, ELogLevel>& levelOverrides) -> std::optional<ELogLevel> { + for (const auto& [prefix, level] : levelOverrides) { + if (message.StartsWith(prefix)) { + return level; + } + } + return std::nullopt; + }; + + anchor->Suppressed.store(isPrefixOf(anchor->AnchorMessage, config->SuppressedMessages)); + anchor->LevelOverride.store(findByPrefix(anchor->AnchorMessage, config->MessageLevelOverrides)); + anchor->CurrentVersion.store(GetVersion()); + } + static TString BuildAnchorMessage(::TSourceLocation sourceLocation, TStringBuf message) { if (message) { diff --git a/yt/yt/core/logging/unittests/logging_ut.cpp b/yt/yt/core/logging/unittests/logging_ut.cpp index c967675ae1..1abc7fe271 100644 --- a/yt/yt/core/logging/unittests/logging_ut.cpp +++ b/yt/yt/core/logging/unittests/logging_ut.cpp @@ -224,14 +224,14 @@ TEST_F(TLoggingTest, ReloadOnSighup) Configure(Format(R"({ rules = [ { - "min_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + writers = [ info ]; }; ]; - "writers" = { - "info" = { - "file_name" = "%v"; - "type" = "file"; + writers = { + info = { + file_name = "%v"; + type = "file"; }; }; })", logFile.Name())); @@ -272,14 +272,14 @@ TEST_F(TLoggingTest, ReloadOnRename) watch_period = 1000; rules = [ { - "min_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + writers = [ info ]; }; ]; - "writers" = { - "info" = { - "file_name" = "%v"; - "type" = "file"; + writers = { + info = { + file_name = "%v"; + type = "file"; }; }; })", logFile.Name())); @@ -442,22 +442,22 @@ TEST_F(TLoggingTest, LogManager) Configure(Format(R"({ rules = [ { - "min_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + writers = [ info ]; }; { - "min_level" = "error"; - "writers" = [ "error" ]; + min_level = "error"; + writers = [ "error" ]; }; ]; - "writers" = { + writers = { "error" = { - "file_name" = "%v"; - "type" = "file"; + file_name = "%v"; + type = "file"; }; - "info" = { - "file_name" = "%v"; - "type" = "file"; + info = { + file_name = "%v"; + type = "file"; }; }; })", errorFile.Name(), infoFile.Name())); @@ -486,14 +486,14 @@ TEST_F(TLoggingTest, ThreadMinLogLevel) Configure(Format(R"({ rules = [ { - "min_level" = "debug"; - "writers" = [ "debug" ]; + min_level = "debug"; + writers = [ "debug" ]; }; ]; - "writers" = { + writers = { "debug" = { - "file_name" = "%v"; - "type" = "file"; + file_name = "%v"; + type = "file"; }; }; })", debugFile.Name())); @@ -702,15 +702,15 @@ TEST_F(TLoggingTest, StructuredLoggingWithValidator) rules = [ { "family" = "structured"; - "min_level" = "info"; - "writers" = [ "test" ]; + min_level = info; + writers = [ "test" ]; }; ]; - "writers" = { + writers = { "test" = { "format" = "structured"; - "file_name" = "%v"; - "type" = "file"; + file_name = "%v"; + type = "file"; }; }; "structured_validation_sampling_rate" = 1.0; @@ -752,15 +752,15 @@ TEST_F(TLoggingTest, StructuredValidationWithSamplingRate) rules = [ { "family" = "structured"; - "min_level" = "info"; - "writers" = [ "test" ]; + min_level = info; + writers = [ "test" ]; }; ]; - "writers" = { + writers = { "test" = { - "file_name" = "%v"; + file_name = "%v"; "format" = "structured"; - "type" = "file"; + type = "file"; } }; "structured_validation_sampling_rate" = 0.5; @@ -842,15 +842,15 @@ TEST_P(TBuiltinRotationTest, All) flush_period = 100; rules = [ { - "min_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + writers = [ info ]; }; ]; - "writers" = { - "info" = { - "file_name" = "%v"; + writers = { + info = { + file_name = "%v"; "use_timestamp_suffix" = %v; - "type" = "file"; + type = "file"; "rotation_policy" = { "max_segment_count_to_keep" = %v; "max_segment_size" = 10; @@ -1062,14 +1062,14 @@ TEST_F(TLoggingTest, DISABLED_LogFatal) Configure(Format(R"({ rules = [ { - "min_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + writers = [ info ]; }; ]; - "writers" = { - "info" = { - "file_name" = "%v"; - "type" = "file"; + writers = { + info = { + file_name = "%v"; + type = "file"; }; }; })", logFile.Name())); @@ -1084,21 +1084,21 @@ TEST_F(TLoggingTest, DISABLED_LogFatal) // Windows does not support request tracing for now. #ifndef _win_ -TEST_F(TLoggingTest, RequestSuppression) +TEST_F(TLoggingTest, SupressedRequests) { TTempFile logFile(GenerateLogFileName()); Configure(Format(R"({ rules = [ { - "min_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + writers = [ info ]; }; ]; - "writers" = { - "info" = { - "file_name" = "%v"; - "type" = "file"; + writers = { + info = { + file_name = "%v"; + type = "file"; }; }; "request_suppression_timeout" = 100; @@ -1125,6 +1125,73 @@ TEST_F(TLoggingTest, RequestSuppression) } #endif +TEST_F(TLoggingTest, SuppressedMessages) +{ + TTempFile logFile(GenerateLogFileName()); + + Configure(Format(R"({ + rules = [ + { + min_level = info; + writers = [ info ]; + }; + ]; + writers = { + info = { + file_name = "%v"; + type = "file"; + }; + }; + suppressed_messages = ["Suppressed message"]; + })", logFile.Name())); + + YT_LOG_INFO("Suppressed message 1"); + YT_LOG_INFO("Suppressed message 2"); + YT_LOG_INFO("Good message"); + + TLogManager::Get()->Synchronize(); + + auto lines = ReadPlainTextEvents(logFile.Name()); + EXPECT_EQ(1, std::ssize(lines)); + EXPECT_TRUE(lines[0].find("Good message") != TString::npos); +} + +TEST_F(TLoggingTest, MessageLevelOverride) +{ + TTempFile logFile(GenerateLogFileName()); + + Configure(Format(R"({ + rules = [ + { + min_level = info; + writers = [ info ]; + }; + ]; + writers = { + info = { + file_name = "%v"; + type = "file"; + }; + }; + message_level_overrides = { + "Overridden message" = "info"; + }; + })", logFile.Name())); + + YT_LOG_INFO("Overridden message 1"); + YT_LOG_TRACE("Overridden message 2"); + YT_LOG_INFO("Good message"); + + TLogManager::Get()->Synchronize(); + + auto lines = ReadPlainTextEvents(logFile.Name()); + for (auto l : lines) Cerr << l << Endl; + EXPECT_EQ(3, std::ssize(lines)); + EXPECT_TRUE(lines[0].find("Overridden message 1") != TString::npos); + EXPECT_TRUE(lines[1].find("Overridden message 2") != TString::npos); + EXPECT_TRUE(lines[2].find("Good message") != TString::npos); +} + //////////////////////////////////////////////////////////////////////////////// class TLoggingTagsTest @@ -1198,15 +1265,15 @@ protected: Configure(Format(R"({ rules = [ { - "min_level" = "info"; - "max_level" = "info"; - "writers" = [ "info" ]; + min_level = info; + "max_level" = info; + writers = [ info ]; }; ]; - "writers" = { - "info" = { - "file_name" = "%v"; - "type" = "file"; + writers = { + info = { + file_name = "%v"; + type = "file"; }; }; })", fileName)); @@ -1388,9 +1455,9 @@ TEST_F(TCustomWriterTest, UnknownWriterType) { Configure(R"({ "rules" = []; - "writers" = { + writers = { "custom" = { - "type" = "unknown"; + type = "unknown"; }; }; })"); @@ -1404,9 +1471,9 @@ TEST_F(TCustomWriterTest, WriterConfigValidation) { Configure(Format(R"({ "rules" = []; - "writers" = { + writers = { "custom" = { - "type" = "%v"; + type = "%v"; "padding" = -10; }; }; @@ -1420,13 +1487,13 @@ TEST_F(TCustomWriterTest, Write) Configure(Format(R"({ "rules" = [ { - "min_level" = "info"; - "writers" = [ "custom" ]; + min_level = info; + writers = [ "custom" ]; } ]; - "writers" = { + writers = { "custom" = { - "type" = "%v"; + type = "%v"; "padding" = 2; }; }; |