From 1482cc1d2bec73bb7c5aa00ccb708ab0c4d0583d Mon Sep 17 00:00:00 2001 From: ohadvano Date: Thu, 8 Jun 2023 20:33:07 +0300 Subject: [PATCH 1/5] initial implementation of tagged logs Signed-off-by: ohadvano --- source/common/common/logger.cc | 19 +++++++++++++++++++ source/common/common/logger.h | 23 +++++++++++++++++++++++ 2 files changed, 42 insertions(+) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index 476f2e06a9f9a..9ed6d6b2a99e7 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -3,6 +3,7 @@ #include // use direct system-assert to avoid cyclic dependency. #include #include +#include #include #include @@ -306,6 +307,24 @@ void setLogFormatForLogger(spdlog::logger& logger, const std::string& log_format logger.set_formatter(std::move(formatter)); } +std::string serializeLogTags(std::map tags) { + if (tags.empty()) { + return ""; + } + + std::stringstream string_stream; + string_stream << "[Tags: "; + for (const auto& tag : tags) { + string_stream << "\"" << tag.first << "\":\"" << tag.second << "\","; + } + + std::string serialized = string_stream.str(); + serialized.pop_back(); + serialized += "] "; + + return serialized; +} + } // namespace Utility namespace CustomFlagFormatter { diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 28aecaf86640a..afcaa68b07b17 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -401,6 +401,11 @@ namespace Utility { */ void setLogFormatForLogger(spdlog::logger& logger, const std::string& log_format); +/** + * Serializes custom log tags to a string that will be prepended to the log message. + */ +std::string serializeLogTags(std::map tags); + } // namespace Utility // Contains custom flags to introduce user defined flags in log pattern. Reference: @@ -517,6 +522,24 @@ class EscapeMessageJsonString : public spdlog::custom_flag_formatter { */ #define ENVOY_LOG(LEVEL, ...) ENVOY_LOG_TO_LOGGER(ENVOY_LOGGER(), LEVEL, ##__VA_ARGS__) +#define ENVOY_TAGGED_LOG_TO_LOGGER(LOGGER, LEVEL, TAGS, FORMAT, ...) \ + do { \ + if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \ + ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, ::Envoy::Logger::Utility::serializeLogTags(TAGS) + FORMAT,\ + ##__VA_ARGS__); \ + } \ + } while (0) + +/** + * Log with tags which are a map of key and value strings. When ENVOY_TAGGED_LOG is used, the tags + * are serialized and prepended to the log message. + * For example, the map {{"key1","val1","key2","val2"}} would be serialized to: + * [Tags: "key1":"val1","key2":"val2"]. The serialization pattern is defined by + * Envoy::Logger::Utility::serializeLogTags function. + */ +#define ENVOY_TAGGED_LOG(LEVEL, TAGS, FORMAT, ...) \ + ENVOY_TAGGED_LOG_TO_LOGGER(ENVOY_LOGGER(), LEVEL, TAGS, FORMAT, ##__VA_ARGS__) + /** * Log with a stable event name. This allows emitting a log line with a stable name in addition to * the standard log line. The stable log line is passed to custom sinks that may want to intercept From 6a4ef723c16eadda3aa2a5d504c051d6a9667346 Mon Sep 17 00:00:00 2001 From: ohadvano Date: Thu, 8 Jun 2023 20:55:03 +0300 Subject: [PATCH 2/5] fix format Signed-off-by: ohadvano --- source/common/common/logger.cc | 2 +- source/common/common/logger.h | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index 9ed6d6b2a99e7..1bc8cfa4eea67 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -315,7 +315,7 @@ std::string serializeLogTags(std::map tags) { std::stringstream string_stream; string_stream << "[Tags: "; for (const auto& tag : tags) { - string_stream << "\"" << tag.first << "\":\"" << tag.second << "\","; + string_stream << "\"" << tag.first << "\":\"" << tag.second << "\","; } std::string serialized = string_stream.str(); diff --git a/source/common/common/logger.h b/source/common/common/logger.h index afcaa68b07b17..7a9f9bab85d8a 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -525,7 +525,8 @@ class EscapeMessageJsonString : public spdlog::custom_flag_formatter { #define ENVOY_TAGGED_LOG_TO_LOGGER(LOGGER, LEVEL, TAGS, FORMAT, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \ - ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, ::Envoy::Logger::Utility::serializeLogTags(TAGS) + FORMAT,\ + ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, \ + ::Envoy::Logger::Utility::serializeLogTags(TAGS) + FORMAT, \ ##__VA_ARGS__); \ } \ } while (0) From a63073541fdbb10e74ada9801494d97116aa62bc Mon Sep 17 00:00:00 2001 From: ohadvano Date: Tue, 13 Jun 2023 09:15:33 +0300 Subject: [PATCH 3/5] add unit tests Signed-off-by: ohadvano --- source/common/common/logger.cc | 10 +++++----- source/common/common/logger.h | 2 +- test/common/common/logger_test.cc | 19 +++++++++++++++++++ 3 files changed, 25 insertions(+), 6 deletions(-) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index 1bc8cfa4eea67..74cee4d084e4c 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -307,18 +307,18 @@ void setLogFormatForLogger(spdlog::logger& logger, const std::string& log_format logger.set_formatter(std::move(formatter)); } -std::string serializeLogTags(std::map tags) { +std::string serializeLogTags(const std::map& tags) { if (tags.empty()) { return ""; } - std::stringstream string_stream; - string_stream << "[Tags: "; + std::stringstream tags_stream; + tags_stream << "[Tags: "; for (const auto& tag : tags) { - string_stream << "\"" << tag.first << "\":\"" << tag.second << "\","; + tags_stream << "\"" << tag.first << "\":\"" << tag.second << "\","; } - std::string serialized = string_stream.str(); + std::string serialized = tags_stream.str(); serialized.pop_back(); serialized += "] "; diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 7a9f9bab85d8a..720e9b1bb68d7 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -404,7 +404,7 @@ void setLogFormatForLogger(spdlog::logger& logger, const std::string& log_format /** * Serializes custom log tags to a string that will be prepended to the log message. */ -std::string serializeLogTags(std::map tags); +std::string serializeLogTags(const std::map& tags); } // namespace Utility diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index e9998db311e3b..9d04059fc88e4 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -384,6 +384,25 @@ TEST(LoggerTest, TestJsonFormatWithNestedJsonMessage) { ENVOY_LOG_MISC(info, "{\"nested_message\":\"hello\"}"); } +TEST(LoggerUtilityTest, TestSerializeLogTags) { + // No entries + EXPECT_EQ("", Envoy::Logger::Utility::serializeLogTags({})); + + // Empty key or value + EXPECT_EQ("[Tags: \"\":\"\"] ", Envoy::Logger::Utility::serializeLogTags({{"", ""}})); + EXPECT_EQ("[Tags: \"\":\"value\"] ", Envoy::Logger::Utility::serializeLogTags({{"", "value"}})); + EXPECT_EQ("[Tags: \"key\":\"\"] ", Envoy::Logger::Utility::serializeLogTags({{"key", ""}})); + + // Single entry + EXPECT_EQ("[Tags: \"key\":\"value\"] ", + Envoy::Logger::Utility::serializeLogTags({{"key", "value"}})); + + // Multiple enties + EXPECT_EQ("[Tags: \"key1\":\"value1\",\"key2\":\"value2\",\"key3\":\"value3\"] ", + Envoy::Logger::Utility::serializeLogTags( + {{"key1", "value1"}, {"key2", "value2"}, {"key3", "value3"}})); +} + } // namespace } // namespace Logger } // namespace Envoy From a060b796f09725e11d4365668b8d427873d5e05e Mon Sep 17 00:00:00 2001 From: ohadvano Date: Tue, 13 Jun 2023 10:01:39 +0300 Subject: [PATCH 4/5] add unit tests Signed-off-by: ohadvano --- test/common/common/log_macros_test.cc | 4 ++++ test/common/common/logger_test.cc | 29 +++++++++++++++++++++++++++ 2 files changed, 33 insertions(+) diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc index 5058e032f35f3..aaa9dce4154af 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -32,11 +32,15 @@ class TestFilterLog : public Logger::Loggable { ENVOY_STREAM_LOG(info, "fake message", stream_); ENVOY_CONN_LOG(error, "fake error", connection_); ENVOY_STREAM_LOG(error, "fake error", stream_); + ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val"); + ENVOY_TAGGED_LOG(info, (std::map{{"key", "val"}}), "fake message {}", + "val"); } void logMessageEscapeSequences() { ENVOY_LOG_MISC(info, "line 1 \n line 2 \t tab \\r test"); } private: + std::map tags_{{"key", "val"}}; NiceMock connection_; NiceMock stream_; }; diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index 9d04059fc88e4..c55a5f3b8fb6d 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -403,6 +403,35 @@ TEST(LoggerUtilityTest, TestSerializeLogTags) { {{"key1", "value1"}, {"key2", "value2"}, {"key3", "value3"}})); } +class ClassForTaggedLog : public Envoy::Logger::Loggable { +public: + void logMessageWithPreCreatedTags() { ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val"); } + + void logMessageWithInlineTags() { + ENVOY_TAGGED_LOG(info, (std::map{{"key_inline", "val"}}), + "fake message {}", "val"); + } + +private: + std::map tags_{{"key", "val"}}; +}; + +TEST(TaggedLogTest, TestTaggedLog) { + Envoy::Logger::Registry::setLogFormat("%v"); + MockLogSink sink(Envoy::Logger::Registry::getSink()); + EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT(msg, HasSubstr("[Tags: \"key\":\"val\"] fake message val")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT(msg, HasSubstr("[Tags: \"key_inline\":\"val\"] fake message val")); + })); + + ClassForTaggedLog object; + object.logMessageWithPreCreatedTags(); + object.logMessageWithInlineTags(); +} + } // namespace } // namespace Logger } // namespace Envoy From f722104c0ef2173d02d6b0214f9bc4d1033ca9e4 Mon Sep 17 00:00:00 2001 From: ohadvano Date: Tue, 13 Jun 2023 10:14:06 +0300 Subject: [PATCH 5/5] fix typo Signed-off-by: ohadvano --- test/common/common/logger_test.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index c55a5f3b8fb6d..d9e039a4d517b 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -397,7 +397,7 @@ TEST(LoggerUtilityTest, TestSerializeLogTags) { EXPECT_EQ("[Tags: \"key\":\"value\"] ", Envoy::Logger::Utility::serializeLogTags({{"key", "value"}})); - // Multiple enties + // Multiple entries EXPECT_EQ("[Tags: \"key1\":\"value1\",\"key2\":\"value2\",\"key3\":\"value3\"] ", Envoy::Logger::Utility::serializeLogTags( {{"key1", "value1"}, {"key2", "value2"}, {"key3", "value3"}}));