Skip to content

application logs: add ENVOY_TAGGED_CONN_LOG and ENVOY_TAGGED_STREAM_LOG #28117

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
yanavlasov merged 5 commits into from
Jun 26, 2023
Merged

application logs: add ENVOY_TAGGED_CONN_LOG and ENVOY_TAGGED_STREAM_LOG #28117

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
a76e03e
initial implementation
ohadvano Jun 22, 2023
d222783
add tests
ohadvano Jun 22, 2023
c61f622
fix format
ohadvano Jun 23, 2023
6de4098
add test and comment
ohadvano Jun 23, 2023
fa30447
fix format
ohadvano Jun 23, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
38 changes: 38 additions & 0 deletions source/common/common/logger.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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
Expand Down
2 changes: 2 additions & 0 deletions test/common/common/BUILD
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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",
],
)

Expand Down
6 changes: 6 additions & 0 deletions test/common/common/log_macros_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,12 @@ class TestFilterLog : public Logger::Loggable<Logger::Id::filter> {
ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val");
ENVOY_TAGGED_LOG(info, (std::map<std::string, std::string>{{"key", "val"}}), "fake message {}",
"val");
ENVOY_TAGGED_CONN_LOG(info, tags_, connection_, "fake message {}", "val");
ENVOY_TAGGED_CONN_LOG(info, (std::map<std::string, std::string>{{"key", "val"}}), connection_,
"fake message {}", "val");
ENVOY_TAGGED_STREAM_LOG(info, tags_, stream_, "fake message {}", "val");
ENVOY_TAGGED_STREAM_LOG(info, (std::map<std::string, std::string>{{"key", "val"}}), stream_,
"fake message {}", "val");
}

void logMessageEscapeSequences() { ENVOY_LOG_MISC(info, "line 1 \n line 2 \t tab \\r test"); }
Expand Down
182 changes: 175 additions & 7 deletions test/common/common/logger_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand All @@ -13,6 +15,7 @@
using testing::_;
using testing::HasSubstr;
using testing::Invoke;
using testing::Return;

namespace Envoy {
namespace Logger {
Expand Down Expand Up @@ -448,6 +451,13 @@ TEST(LoggerUtilityTest, TestSerializeLogTags) {

class ClassForTaggedLog : public Envoy::Logger::Loggable<Envoy::Logger::Id::filter> {
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<const Network::Connection&>(connection_))));
}

void logMessageWithPreCreatedTags() { ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val"); }

void logMessageWithInlineTags() {
Expand All @@ -459,15 +469,29 @@ class ClassForTaggedLog : public Envoy::Logger::Loggable<Envoy::Logger::Id::filt
ENVOY_TAGGED_LOG(info, tags_with_escaping_, "fake me\"ssage {}", "val");
}

void logMessageWithConnection(std::map<std::string, std::string>& tags) {
ENVOY_TAGGED_CONN_LOG(info, tags, connection_, "fake message");
}

void logMessageWithStream(std::map<std::string, std::string>& tags) {
ENVOY_TAGGED_STREAM_LOG(info, tags, stream_, "fake message");
}

private:
std::map<std::string, std::string> tags_{{"key", "val"}};
std::map<std::string, std::string> tags_with_escaping_{{"key", "val"}, {"ke\"y", "v\"al"}};
NiceMock<Network::MockConnection> connection_;
NiceMock<Http::MockStreamDecoderFilterCallbacks> 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"));
}))
Expand All @@ -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<std::string, std::string> empty_tags;
std::map<std::string, std::string> tags{{"key", "val"}};
std::map<std::string, std::string> 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<std::string, std::string> empty_tags;
std::map<std::string, std::string> tags{{"key", "val"}};
std::map<std::string, std::string> 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");
Expand All @@ -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\""));
Expand All @@ -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<std::string, std::string> empty_tags;
std::map<std::string, std::string> 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<std::string, std::string> empty_tags;
std::map<std::string, std::string> 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");
Expand All @@ -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();
Expand Down