diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 45ded08522778..3886a5eae5d9a 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -573,6 +573,28 @@ class ExtractedMessage : public spdlog::custom_flag_formatter { } \ } while (0) +#define ENVOY_TAGGED_CONN_LOG_TO_LOGGER(LOGGER, LEVEL, TAGS, CONNECTION, FORMAT, ...) \ + do { \ + if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \ + TAGS.emplace("ConnectionId", std::to_string((CONNECTION).id())); \ + ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, \ + ::Envoy::Logger::Utility::serializeLogTags(TAGS) + FORMAT, \ + ##__VA_ARGS__); \ + } \ + } while (0) + +#define ENVOY_TAGGED_STREAM_LOG_TO_LOGGER(LOGGER, LEVEL, TAGS, STREAM, FORMAT, ...) \ + do { \ + if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \ + TAGS.emplace("ConnectionId", \ + (STREAM).connection() ? std::to_string((STREAM).connection()->id()) : "0"); \ + TAGS.emplace("StreamId", std::to_string((STREAM).streamId())); \ + 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. @@ -583,6 +605,22 @@ class ExtractedMessage : public spdlog::custom_flag_formatter { #define ENVOY_TAGGED_LOG(LEVEL, TAGS, FORMAT, ...) \ ENVOY_TAGGED_LOG_TO_LOGGER(ENVOY_LOGGER(), LEVEL, TAGS, FORMAT, ##__VA_ARGS__) +/** + * Log with tags which are a map of key and value strings. Has the same operation as + * ENVOY_TAGGED_LOG, only this macro will also add the connection ID to the tags, if the provided + * tags do not already have a ConnectionId key existing. + */ +#define ENVOY_TAGGED_CONN_LOG(LEVEL, TAGS, CONNECTION, FORMAT, ...) \ + ENVOY_TAGGED_CONN_LOG_TO_LOGGER(ENVOY_LOGGER(), LEVEL, TAGS, CONNECTION, FORMAT, ##__VA_ARGS__) + +/** + * Log with tags which are a map of key and value strings. Has the same operation as + * ENVOY_TAGGED_LOG, only this macro will also add the connection and stream ID to the tags, + * if the provided tags do not already have a ConnectionId or StreamId keys existing. + */ +#define ENVOY_TAGGED_STREAM_LOG(LEVEL, TAGS, STREAM, FORMAT, ...) \ + ENVOY_TAGGED_STREAM_LOG_TO_LOGGER(ENVOY_LOGGER(), LEVEL, TAGS, STREAM, 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 diff --git a/test/common/common/BUILD b/test/common/common/BUILD index 74f86504f154a..6ef06e492d2fa 100644 --- a/test/common/common/BUILD +++ b/test/common/common/BUILD @@ -212,6 +212,8 @@ envoy_cc_test( srcs = ["logger_test.cc"], deps = [ "//source/common/common:minimal_logger_lib", + "//test/mocks/http:http_mocks", + "//test/mocks/network:network_mocks", ], ) diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc index aaa9dce4154af..cb9e86515ca2f 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -35,6 +35,12 @@ class TestFilterLog : public Logger::Loggable { ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val"); ENVOY_TAGGED_LOG(info, (std::map{{"key", "val"}}), "fake message {}", "val"); + ENVOY_TAGGED_CONN_LOG(info, tags_, connection_, "fake message {}", "val"); + ENVOY_TAGGED_CONN_LOG(info, (std::map{{"key", "val"}}), connection_, + "fake message {}", "val"); + ENVOY_TAGGED_STREAM_LOG(info, tags_, stream_, "fake message {}", "val"); + ENVOY_TAGGED_STREAM_LOG(info, (std::map{{"key", "val"}}), stream_, + "fake message {}", "val"); } void logMessageEscapeSequences() { ENVOY_LOG_MISC(info, "line 1 \n line 2 \t tab \\r test"); } diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index 86a4e9803176d..6a3c8ae1882fd 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -5,6 +5,8 @@ #include "source/common/common/logger.h" #include "test/mocks/common.h" +#include "test/mocks/http/mocks.h" +#include "test/mocks/network/mocks.h" #include "test/test_common/environment.h" #include "gmock/gmock.h" @@ -13,6 +15,7 @@ using testing::_; using testing::HasSubstr; using testing::Invoke; +using testing::Return; namespace Envoy { namespace Logger { @@ -448,6 +451,13 @@ TEST(LoggerUtilityTest, TestSerializeLogTags) { class ClassForTaggedLog : public Envoy::Logger::Loggable { public: + ClassForTaggedLog() { + EXPECT_CALL(connection_, id()).WillRepeatedly(Return(200)); + EXPECT_CALL(stream_, streamId()).WillRepeatedly(Return(300)); + EXPECT_CALL(stream_, connection()) + .WillRepeatedly(Return(makeOptRef(dynamic_cast(connection_)))); + } + void logMessageWithPreCreatedTags() { ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val"); } void logMessageWithInlineTags() { @@ -459,15 +469,29 @@ class ClassForTaggedLog : public Envoy::Logger::Loggable& tags) { + ENVOY_TAGGED_CONN_LOG(info, tags, connection_, "fake message"); + } + + void logMessageWithStream(std::map& tags) { + ENVOY_TAGGED_STREAM_LOG(info, tags, stream_, "fake message"); + } + private: std::map tags_{{"key", "val"}}; std::map tags_with_escaping_{{"key", "val"}, {"ke\"y", "v\"al"}}; + NiceMock connection_; + NiceMock stream_; }; TEST(TaggedLogTest, TestTaggedLog) { Envoy::Logger::Registry::setLogFormat("%v"); MockLogSink sink(Envoy::Logger::Registry::getSink()); EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) .WillOnce(Invoke([](auto msg, auto&) { EXPECT_THAT(msg, HasSubstr("[Tags: \"key\":\"val\"] fake message val")); })) @@ -485,6 +509,67 @@ TEST(TaggedLogTest, TestTaggedLog) { object.logMessageWithEscaping(); } +TEST(TaggedLogTest, TestTaggedConnLog) { + Envoy::Logger::Registry::setLogFormat("%v"); + MockLogSink sink(Envoy::Logger::Registry::getSink()); + EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT(msg, HasSubstr("[Tags: \"ConnectionId\":\"200\"] fake message")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT(msg, + HasSubstr("[Tags: \"ConnectionId\":\"200\",\"key\":\"val\"] fake message")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT(msg, HasSubstr("[Tags: \"ConnectionId\":\"105\"] fake message")); + })); + + std::map empty_tags; + std::map tags{{"key", "val"}}; + std::map tags_with_conn_id{{"ConnectionId", "105"}}; + + ClassForTaggedLog object; + object.logMessageWithConnection(empty_tags); + object.logMessageWithConnection(tags); + object.logMessageWithConnection(tags_with_conn_id); +} + +TEST(TaggedLogTest, TestTaggedStreamLog) { + Envoy::Logger::Registry::setLogFormat("%v"); + MockLogSink sink(Envoy::Logger::Registry::getSink()); + EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT( + msg, HasSubstr("[Tags: \"ConnectionId\":\"200\",\"StreamId\":\"300\"] fake message")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT( + msg, HasSubstr("[Tags: \"ConnectionId\":\"200\",\"StreamId\":\"300\",\"key\":\"val\"] " + "fake message")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_THAT( + msg, HasSubstr("[Tags: \"ConnectionId\":\"200\",\"StreamId\":\"405\"] fake message")); + })); + + std::map empty_tags; + std::map tags{{"key", "val"}}; + std::map tags_with_stream_id{{"StreamId", "405"}}; + + ClassForTaggedLog object; + object.logMessageWithStream(empty_tags); + object.logMessageWithStream(tags); + object.logMessageWithStream(tags_with_stream_id); +} + TEST(TaggedLogTest, TestTaggedLogWithJsonFormat) { ProtobufWkt::Struct log_struct; (*log_struct.mutable_fields())["Level"].set_string_value("%l"); @@ -495,6 +580,10 @@ TEST(TaggedLogTest, TestTaggedLogWithJsonFormat) { MockLogSink sink(Envoy::Logger::Registry::getSink()); EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) .WillOnce(Invoke([](auto msg, auto&) { EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); @@ -514,6 +603,80 @@ TEST(TaggedLogTest, TestTaggedLogWithJsonFormat) { object.logMessageWithEscaping(); } +TEST(TaggedLogTest, TestTaggedConnLogWithJsonFormat) { + ProtobufWkt::Struct log_struct; + (*log_struct.mutable_fields())["Level"].set_string_value("%l"); + (*log_struct.mutable_fields())["Message"].set_string_value("%j"); + Envoy::Logger::Registry::setLogLevel(spdlog::level::info); + EXPECT_TRUE(Envoy::Logger::Registry::setJsonLogFormat(log_struct).ok()); + EXPECT_TRUE(Envoy::Logger::Registry::jsonLogFormatSet()); + + MockLogSink sink(Envoy::Logger::Registry::getSink()); + EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); + EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); + EXPECT_THAT(msg, HasSubstr("\"Message\":\"fake message\"")); + EXPECT_THAT(msg, HasSubstr("\"ConnectionId\":\"200\"")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); + EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); + EXPECT_THAT(msg, HasSubstr("\"Message\":\"fake message\"")); + EXPECT_THAT(msg, HasSubstr("\"key\":\"val\"")); + EXPECT_THAT(msg, HasSubstr("\"ConnectionId\":\"200\"")); + })); + + std::map empty_tags; + std::map tags{{"key", "val"}}; + + ClassForTaggedLog object; + object.logMessageWithConnection(empty_tags); + object.logMessageWithConnection(tags); +} + +TEST(TaggedLogTest, TestTaggedStreamLogWithJsonFormat) { + ProtobufWkt::Struct log_struct; + (*log_struct.mutable_fields())["Level"].set_string_value("%l"); + (*log_struct.mutable_fields())["Message"].set_string_value("%j"); + Envoy::Logger::Registry::setLogLevel(spdlog::level::info); + EXPECT_TRUE(Envoy::Logger::Registry::setJsonLogFormat(log_struct).ok()); + EXPECT_TRUE(Envoy::Logger::Registry::jsonLogFormatSet()); + + MockLogSink sink(Envoy::Logger::Registry::getSink()); + EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); + EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); + EXPECT_THAT(msg, HasSubstr("\"Message\":\"fake message\"")); + EXPECT_THAT(msg, HasSubstr("\"StreamId\":\"300\"")); + EXPECT_THAT(msg, HasSubstr("\"ConnectionId\":\"200\"")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); + EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); + EXPECT_THAT(msg, HasSubstr("\"Message\":\"fake message\"")); + EXPECT_THAT(msg, HasSubstr("\"key\":\"val\"")); + EXPECT_THAT(msg, HasSubstr("\"StreamId\":\"300\"")); + EXPECT_THAT(msg, HasSubstr("\"ConnectionId\":\"200\"")); + })); + + std::map empty_tags; + std::map tags{{"key", "val"}}; + + ClassForTaggedLog object; + object.logMessageWithStream(empty_tags); + object.logMessageWithStream(tags); +} + TEST(TaggedLogTest, TestTaggedLogWithJsonFormatMultipleJFlags) { ProtobufWkt::Struct log_struct; (*log_struct.mutable_fields())["Level"].set_string_value("%l"); @@ -524,13 +687,18 @@ TEST(TaggedLogTest, TestTaggedLogWithJsonFormatMultipleJFlags) { EXPECT_TRUE(Envoy::Logger::Registry::jsonLogFormatSet()); MockLogSink sink(Envoy::Logger::Registry::getSink()); - EXPECT_CALL(sink, log(_, _)).WillOnce(Invoke([](auto msg, auto&) { - EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); - EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); - EXPECT_THAT(msg, HasSubstr("\"Message1\":\"fake message val\"")); - EXPECT_THAT(msg, HasSubstr("\"Message2\":\"fake message val\"")); - EXPECT_THAT(msg, HasSubstr("\"key\":\"val\"")); - })); + EXPECT_CALL(sink, log(_, _)) + .WillOnce(Invoke([](auto msg, auto&) { + // Using the mock connection write a log, skipping it. + EXPECT_THAT(msg, HasSubstr("TestRandomGenerator")); + })) + .WillOnce(Invoke([](auto msg, auto&) { + EXPECT_NO_THROW(Json::Factory::loadFromString(std::string(msg))); + EXPECT_THAT(msg, HasSubstr("\"Level\":\"info\"")); + EXPECT_THAT(msg, HasSubstr("\"Message1\":\"fake message val\"")); + EXPECT_THAT(msg, HasSubstr("\"Message2\":\"fake message val\"")); + EXPECT_THAT(msg, HasSubstr("\"key\":\"val\"")); + })); ClassForTaggedLog object; object.logMessageWithPreCreatedTags();