Skip to content

logging: Add ENVOY_TAGGED_LOG macro to enable tagged logging #27882

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
mattklein123 merged 5 commits into from
Jun 14, 2023
Merged

logging: Add ENVOY_TAGGED_LOG macro to enable tagged logging #27882

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
1482cc1
initial implementation of tagged logs
ohadvano Jun 8, 2023
6a4ef72
fix format
ohadvano Jun 8, 2023
a630735
add unit tests
ohadvano Jun 13, 2023
a060b79
add unit tests
ohadvano Jun 13, 2023
f722104
fix typo
ohadvano Jun 13, 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
19 changes: 19 additions & 0 deletions source/common/common/logger.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
#include <cassert> // use direct system-assert to avoid cyclic dependency.
#include <cstdint>
#include <iostream>
#include <sstream>
#include <string>
#include <vector>

Expand Down Expand Up @@ -306,6 +307,24 @@ void setLogFormatForLogger(spdlog::logger& logger, const std::string& log_format
logger.set_formatter(std::move(formatter));
}

std::string serializeLogTags(const std::map<std::string, std::string>& tags) {
if (tags.empty()) {
return "";
}

std::stringstream tags_stream;
tags_stream << "[Tags: ";
for (const auto& tag : tags) {
tags_stream << "\"" << tag.first << "\":\"" << tag.second << "\",";
}

std::string serialized = tags_stream.str();
serialized.pop_back();
serialized += "] ";

return serialized;
}

} // namespace Utility

namespace CustomFlagFormatter {
Expand Down
24 changes: 24 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 @@ -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(const std::map<std::string, std::string>& tags);

} // namespace Utility

// Contains custom flags to introduce user defined flags in log pattern. Reference:
Expand Down Expand Up @@ -517,6 +522,25 @@ 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)) { \
Copy link
Contributor Author

@ohadvano ohadvano Jun 12, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mattklein123 I added this check for the logger level before doing the serialization and proceeding with the costlier operations - are there more checks I have missed that should be added?

Copy link
Member

@mattklein123 mattklein123 Jun 12, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In your example you construct the map outside of the macro. We would optimally like to construct the map inside the macro if possible. Can you try that out?

Copy link
Contributor Author

@ohadvano ohadvano Jun 12, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To make sure I understand you correctly - do you mean to move the code of serializeLogTags to inside the macro?

Copy link
Contributor Author

@ohadvano ohadvano Jun 12, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Or have you meant the usage exmple of

std::map<std::string, std::string> tags{{"key", "val"}, {"key2", "val2"}};
ENVOY_TAGGED_LOG(info, tags, "some_message {}", "val");

The idea was that this map could have been pre-created and saved in some class member to be reused in multiple ENVOY_TAGGED_LOG calls.

Can you demonstrate an alternative usage example so I could better understand please?

Copy link
Member

@mattklein123 mattklein123 Jun 12, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What I mean is I could imagine doing something like:

ENVOY_TAGGED_LOG(info, {make tags here somehow}, "some_message {}", "val");

I just want to make sure that works correctly also.

Copy link
Contributor Author

@ohadvano ohadvano Jun 12, 2023

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Best option I could find is wrapping the tags map in parentheses, for example:

ENVOY_TAGGED_LOG(info, (std::map<std::string, std::string>{{"key", "val"}}), "some_message {}", "val");

If you define some using for example using LogTagsMap = std::map<std::string, std::string> then it would look like ENVOY_TAGGED_LOG(info, (LogTagsMap{{"key", "val"}}), "some_message {}", "val");, which is a bit nicer.

It's a bit awkward, but it works.. wdyt?

Copy link
Contributor Author

@ohadvano ohadvano Jun 13, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added tests that demonstrate and validate the two ways to use the macro, the PR is ready for review

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
Expand Down
4 changes: 4 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 @@ -32,11 +32,15 @@ class TestFilterLog : public Logger::Loggable<Logger::Id::filter> {
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<std::string, std::string>{{"key", "val"}}), "fake message {}",
"val");
}

void logMessageEscapeSequences() { ENVOY_LOG_MISC(info, "line 1 \n line 2 \t tab \\r test"); }

private:
std::map<std::string, std::string> tags_{{"key", "val"}};
NiceMock<Network::MockConnection> connection_;
NiceMock<Http::MockStreamDecoderFilterCallbacks> stream_;
};
Expand Down
48 changes: 48 additions & 0 deletions test/common/common/logger_test.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -384,6 +384,54 @@ 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 entries
EXPECT_EQ("[Tags: \"key1\":\"value1\",\"key2\":\"value2\",\"key3\":\"value3\"] ",
Envoy::Logger::Utility::serializeLogTags(
{{"key1", "value1"}, {"key2", "value2"}, {"key3", "value3"}}));
}

class ClassForTaggedLog : public Envoy::Logger::Loggable<Envoy::Logger::Id::filter> {
public:
void logMessageWithPreCreatedTags() { ENVOY_TAGGED_LOG(info, tags_, "fake message {}", "val"); }

void logMessageWithInlineTags() {
ENVOY_TAGGED_LOG(info, (std::map<std::string, std::string>{{"key_inline", "val"}}),
"fake message {}", "val");
}

private:
std::map<std::string, std::string> 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