Skip to content

logger: macros evaluate logging level before invoking logger #2676

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
ggreenway merged 4 commits into from
Mar 2, 2018
+69 −7
Merged

logger: macros evaluate logging level before invoking logger #2676

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
76b4d13
Changed main logging macro to compare logger's severity level to mess…
cpakulski Feb 26, 2018
27a9b7f
Changed main LOGGER macro to be used as a statement.
cpakulski Feb 27, 2018
ef37d67
Fixed compile problem when Logger macro is invoked from outside the E…
cpakulski Feb 28, 2018
3191354
Modified ENVOY_LOG_TO_LOGGER macro to use FQ namespace Envoy::Logger:…
cpakulski Mar 2, 2018
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
22 changes: 21 additions & 1 deletion source/common/common/logger.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,6 +57,21 @@ class Logger {
std::string name() const { return logger_->name(); }
void setLevel(spdlog::level::level_enum level) const { logger_->set_level(level); }

/* This is simple mapping between Logger severity levels and spdlog severity levels.
* The only reason for this mapping is to go around the fact that spdlog defines level as err
* but the method to log at err level is called LOGGER.error not LOGGER.err. All other level are
* fine spdlog::info corresponds to LOGGER.info method.
*/
typedef enum {
trace = spdlog::level::trace,
debug = spdlog::level::debug,
info = spdlog::level::info,
warn = spdlog::level::warn,
error = spdlog::level::err,
critical = spdlog::level::critical,
off = spdlog::level::off
} levels;

private:
Logger(const std::string& name);

Expand Down Expand Up @@ -192,7 +207,12 @@ template <Id id> class Loggable {
/**
* Convenience macro to log to a user-specified logger.
*/
#define ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, ...) ENVOY_LOG_##LEVEL##_TO_LOGGER(LOGGER, ##__VA_ARGS__)
#define ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, ...) \
Copy link
Copy Markdown
Member

@mrice32 mrice32 Feb 26, 2018

Choose a reason for hiding this comment

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

Would you mind adding a test for this? I think this may suffer from the not-a-statement macro issue (see here), but I'm not sure. Specifically, I'm worried about the case:

if (condition) ENVOY_LOG_TO_LOGGER(LOGGER, LEVEL, ...);
else f();

This may be the reason that the behavior at the callsite in source/common/http/filter/lua/lua_filter.cc needed to be updated.

Copy link
Copy Markdown
Contributor Author

@cpakulski cpakulski Feb 27, 2018

Choose a reason for hiding this comment

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

Wrapped macro into do ... while(0) based on the link you sent (thanks!).
I had to keep changes for source/common/http/filter/lua/lua_filter.cc.
spdlog::log ... returns void and statement
return ENVOY_LOG...
was an easy way to log and exit function in one step. It will not work with the new macro.

Copy link
Copy Markdown
Member

@mrice32 mrice32 Feb 27, 2018

Choose a reason for hiding this comment

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

SGTM, thanks!

do { \
if (static_cast<spdlog::level::level_enum>(Envoy::Logger::Logger::LEVEL) >= LOGGER.level()) { \
ENVOY_LOG_##LEVEL##_TO_LOGGER(LOGGER, ##__VA_ARGS__); \
} \
} while (0)

/**
* Convenience macro to get logger.
Expand Down
18 changes: 12 additions & 6 deletions source/common/http/filter/lua/lua_filter.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -481,17 +481,23 @@ void Filter::scriptError(const Envoy::Lua::LuaException& e) {
void Filter::scriptLog(spdlog::level::level_enum level, const char* message) {
switch (level) {
case spdlog::level::trace:
return ENVOY_LOG(trace, "script log: {}", message);
ENVOY_LOG(trace, "script log: {}", message);
return;
case spdlog::level::debug:
return ENVOY_LOG(debug, "script log: {}", message);
ENVOY_LOG(debug, "script log: {}", message);
return;
case spdlog::level::info:
return ENVOY_LOG(info, "script log: {}", message);
ENVOY_LOG(info, "script log: {}", message);
return;
case spdlog::level::warn:
return ENVOY_LOG(warn, "script log: {}", message);
ENVOY_LOG(warn, "script log: {}", message);
return;
case spdlog::level::err:
return ENVOY_LOG(error, "script log: {}", message);
ENVOY_LOG(error, "script log: {}", message);
return;
case spdlog::level::critical:
return ENVOY_LOG(critical, "script log: {}", message);
ENVOY_LOG(critical, "script log: {}", message);
return;
case spdlog::level::off:
NOT_IMPLEMENTED;
}
Expand Down
36 changes: 36 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 @@ -37,4 +37,40 @@ TEST(Logger, All) {
// Misc logging with no facility.
ENVOY_LOG_MISC(info, "fake message");
}

TEST(Logger, evaluateParams) {
uint32_t i = 1;

// set logger's level to low level.
// log message with higher severity and make sure that params were evaluated.
GET_MISC_LOGGER().set_level(spdlog::level::info);
ENVOY_LOG_MISC(warn, "test message '{}'", i++);
ASSERT_THAT(i, testing::Eq(2));
Copy link
Copy Markdown
Member

@ggreenway ggreenway Feb 26, 2018

Choose a reason for hiding this comment

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

EXPECT_EQ(i, 2);

}

TEST(Logger, doNotEvaluateParams) {
uint32_t i = 1;

// set logger's logging level high and log a message with lower severity
// params should not be evaluated.
GET_MISC_LOGGER().set_level(spdlog::level::critical);
ENVOY_LOG_MISC(error, "test message '{}'", i++);
ASSERT_THAT(i, testing::Eq(1));
Copy link
Copy Markdown
Member

@ggreenway ggreenway Feb 26, 2018

Choose a reason for hiding this comment

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

EXPECT_EQ(i, 1);

}

TEST(Logger, logAsStatement) {
// Just log as part of if ... statement

if (true)
ENVOY_LOG_MISC(critical, "test message 1");
else
ENVOY_LOG_MISC(critical, "test message 2");

// do the same with curly brackets
if (true) {
ENVOY_LOG_MISC(critical, "test message 3");
} else {
ENVOY_LOG_MISC(critical, "test message 4");
}
}
} // namespace Envoy