logger: macros evaluate logging level before invoking logger #2676

cpakulski · 2018-02-26T21:34:43Z

Modified main logging macro to compare logger's severity with severity of the message to be logged. If message severity is lower, logger is not called and code passed as params is not evaluated.

…age severity. Code passed to logger as params will NOT be evaluated if message's severity is lower than logger's severity. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

ggreenway

This seems like a nice improvement.

The release build tests are failing with this.

ggreenway · 2018-02-26T21:57:28Z

test/common/common/log_macros_test.cc

+  // 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));


EXPECT_EQ(i, 2);

ggreenway · 2018-02-26T21:57:39Z

test/common/common/log_macros_test.cc

+  // 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));


EXPECT_EQ(i, 1);

ggreenway · 2018-02-26T21:58:10Z

test/common/common/log_macros_test.cc

@@ -37,4 +37,24 @@ TEST(Logger, All) {
  // Misc logging with no facility.
  ENVOY_LOG_MISC(info, "fake message");
 }
+
+TEST(Logger, evaluateParams) {
+  auto i = 1;


Please give this a type: uint32_t i = 1;

OK. Will change that to uint32_t. Thanks.

ggreenway · 2018-02-26T21:58:18Z

test/common/common/log_macros_test.cc

+}
+
+TEST(Logger, doNotEvaluateParams) {
+  auto i = 1;


Please give this a type.

mrice32

Great work! Thanks for adding this! Just one comment about the macro.

mrice32 · 2018-02-26T22:04:51Z

source/common/common/logger.h

@@ -192,7 +207,10 @@ 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, ...)                                                    \


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.

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.

SGTM, thanks!

Added test to verify that the macro can be used inside if .. else ... Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

mrice32

Thanks!

alyssawilk · 2018-02-27T20:15:04Z

I'd be happy to merge today but it looks like the tests are still failing?

cpakulski · 2018-02-27T20:17:32Z

I am working on fixing the problem with CI tests. When ASSERT is used not in Envoy namespace compiler cannot find certain values.

alyssawilk · 2018-02-28T13:57:08Z

@cpakulski one other small request - would you mind editing your original description to match the pull request template? It's helpful for when we commit to have a standard format. thanks!

https://github.com/envoyproxy/envoy/blob/master/PULL_REQUEST_TEMPLATE.md

cpakulski · 2018-02-28T14:36:48Z

@alyssawilk How to run all CI tests on developer's machine? Just want to make sure that it all passes before PR. No problem - I will update description to match the template.

alyssawilk · 2018-02-28T16:10:29Z

I don't think there's a single command to run all of them but for any build you can do something like
./ci/run_envoy_docker.sh ./ci/do_ci.sh bazel.asan
(check out do_ci for the list of other builds)

cpakulski · 2018-02-28T18:55:18Z

Description: logger's current severity level is checked before calling logger's API. This avoids evaluating parameters passed to the logger when message severity is lower than logger's setting. Before this change, params were evaluated even when the message was later on dropped by logger.
Risk Level: Medium. This is simple fix, but the code is extensively used across the project.
Testing: unit tests: added 3 tests to test/common/common/log_macros_test.cc
Docs Changes: N/A
Release Notes: N/A

…nvoy namespace. Signed-off-by: christoph <paker8848@gmail.com>

ggreenway · 2018-03-01T19:03:14Z

test/common/common/utility_speed_test.cc

@@ -7,6 +7,8 @@
 #include "absl/strings/string_view.h"
 #include "testing/base/public/benchmark.h"

+using namespace Envoy;


Can this code be put into namespace Envoy, instead of adding a "using"?

I see two options:

move test code into Envoy namespace (most test code is already in that namespace - only few tests run in default ns)

change MACRO to use FQ namespace Envoy::Logger::Logger instead of Logger::Logger.

I think that first option is a bit cleaner - will try to do that and will ask you to review it. Thanks.

I'm fine with either of those solutions.

…:Logger. There are some benchmark tests which invoke logger from default namespace. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

ggreenway · 2018-03-02T16:21:37Z

This looks good, but somehow you've angered the DCO-bot. I think it's because your DCO-sign-off doesn't match the name in your git commit author. I've never seen that error before.

cpakulski · 2018-03-02T16:25:01Z

@ggreenway Somehow I messed it up - do not know exactly how. I have fixed it in local repo and will push --force to overwrite the latest commit. Just waiting for other circleci tests to finish.

junr03 · 2018-03-05T22:06:10Z

@cpakulski this PR causes compilation failures when running with -DNVLOG because it does not fence evaluating the LOGGER arg behind the appropriate #idnfef. One place that this surfaces is in the connection handler, where the logger instance variable is fenced in https://github.com/envoyproxy/envoy/blob/master/source/server/connection_handler_impl.h#L163-L165, and thus is not present when the macro is evaluated, when you call LOGGER.level() here: https://github.com/envoyproxy/envoy/pull/2676/files#diff-a5a6b6a3e1f886a6a49364ede0758acbR212

This used to not be a problem because the first use of the LOGGER argument in the macro (before this PR) is fenced appropriately:

envoy/source/common/common/logger.h

Lines 179 to 185 in 99d5fe9

    
           #ifdef NVLOG 
        
           #define ENVOY_LOG_trace_TO_LOGGER(LOGGER, ...) 
        
           #define ENVOY_LOG_debug_TO_LOGGER(LOGGER, ...) 
        
           #else 
        
           #define ENVOY_LOG_trace_TO_LOGGER(LOGGER, ...) LOGGER.trace(LOG_PREFIX __VA_ARGS__) 
        
           #define ENVOY_LOG_debug_TO_LOGGER(LOGGER, ...) LOGGER.debug(LOG_PREFIX __VA_ARGS__) 
        
           #endif

I will leave it up to @lita (who is trying to get a deploy out at Lyft) if she wants to revert. And to coordinate with you @cpakulski

cc @alyssawilk @ggreenway

lita · 2018-03-05T22:23:48Z

Yea I am going to have to revert, as I am not able to quickly fix this myself. Feel free to submit another PR with the fix. Thanks!

…nvoyproxy#2676)" This reverts commit 8078092.

lita · 2018-03-05T22:25:58Z

Actually, rather than revert, I will merge lyft's envoy to the change before yours. If you can upstream the fix before Thursday, then there will be no need to revert.

lita · 2018-03-05T22:48:18Z

After further discussion with @ccaraman, we are going to revert this PR.

…nvoyproxy#2676)" This reverts commit 8078092. Signed-off-by: Lita Cho <lcho@lyft.com>

…2676)" (#2730) This reverts commit 8078092. Signed-off-by: Lita Cho <lcho@lyft.com>

Signed-off-by: Alyssa Wilk <alyssar@chromium.org> Signed-off-by: JP Simard <jp@jpsim.com>

Changed main logging macro to compare logger's severity level to mess…

76b4d13

…age severity. Code passed to logger as params will NOT be evaluated if message's severity is lower than logger's severity. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

alyssawilk requested a review from mrice32 February 26, 2018 21:41

ggreenway requested changes Feb 26, 2018

View reviewed changes

mrice32 reviewed Feb 26, 2018

View reviewed changes

Changed main LOGGER macro to be used as a statement.

27a9b7f

Added test to verify that the macro can be used inside if .. else ... Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

ggreenway self-assigned this Feb 27, 2018

ggreenway previously approved these changes Feb 27, 2018

View reviewed changes

ggreenway assigned htuch Feb 27, 2018

mrice32 approved these changes Feb 27, 2018

View reviewed changes

cpakulski changed the title ~~Fix for issue 2330. Macros evaluate logging level before invoking logger~~ logger: macros evaluate logging level before invoking logger Feb 28, 2018

Fixed compile problem when Logger macro is invoked from outside the E…

ef37d67

…nvoy namespace. Signed-off-by: christoph <paker8848@gmail.com>

cpakulski dismissed ggreenway’s stale review via ef37d67 February 28, 2018 18:58

htuch assigned alyssawilk and unassigned htuch Feb 28, 2018

ggreenway reviewed Mar 1, 2018

View reviewed changes

Modified ENVOY_LOG_TO_LOGGER macro to use FQ namespace Envoy::Logger:…

3191354

…:Logger. There are some benchmark tests which invoke logger from default namespace. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

ggreenway previously approved these changes Mar 2, 2018

View reviewed changes

cpakulski dismissed ggreenway’s stale review via 3191354 March 2, 2018 20:20

cpakulski force-pushed the issue/2330 branch from e09710d to 3191354 Compare March 2, 2018 20:20

ggreenway approved these changes Mar 2, 2018

View reviewed changes

ggreenway merged commit 8078092 into envoyproxy:master Mar 2, 2018

lita pushed a commit to lita/envoy that referenced this pull request Mar 5, 2018

Revert "logger: macros evaluate logging level before invoking logger (e…

c2f7655

…nvoyproxy#2676)" This reverts commit 8078092.

lita mentioned this pull request Mar 5, 2018

Revert "logger: macros evaluate logging level before invoking logger" #2727

Closed

lita mentioned this pull request Mar 5, 2018

Revert "logger: macros evaluate logging level before invoking logger" #2729

Closed

lita pushed a commit to lita/envoy that referenced this pull request Mar 5, 2018

Revert "logger: macros evaluate logging level before invoking logger (e…

7fd05e6

…nvoyproxy#2676)" This reverts commit 8078092. Signed-off-by: Lita Cho <lcho@lyft.com>

lita mentioned this pull request Mar 5, 2018

Revert "logger: macros evaluate logging level before invoking logger … #2730

Merged

htuch pushed a commit that referenced this pull request Mar 6, 2018

Revert "logger: macros evaluate logging level before invoking logger (#…

34091d5

…2676)" (#2730) This reverts commit 8078092. Signed-off-by: Lita Cho <lcho@lyft.com>

cpakulski mentioned this pull request Mar 7, 2018

logger: macros evaluate logging level before invoking logger #2751

Merged

jpsim pushed a commit that referenced this pull request Nov 28, 2022

code cleanup for repo merge (#2676)

1041fbb

Signed-off-by: Alyssa Wilk <alyssar@chromium.org> Signed-off-by: JP Simard <jp@jpsim.com>

jpsim pushed a commit that referenced this pull request Nov 29, 2022

code cleanup for repo merge (#2676)

23e1f02

Signed-off-by: Alyssa Wilk <alyssar@chromium.org> Signed-off-by: JP Simard <jp@jpsim.com>

logger: macros evaluate logging level before invoking logger #2676

logger: macros evaluate logging level before invoking logger #2676

Uh oh!

Conversation

cpakulski commented Feb 26, 2018

Uh oh!

ggreenway left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mrice32 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mrice32 left a comment

Choose a reason for hiding this comment

Uh oh!

alyssawilk commented Feb 27, 2018

Uh oh!

cpakulski commented Feb 27, 2018

Uh oh!

alyssawilk commented Feb 28, 2018

Uh oh!

cpakulski commented Feb 28, 2018

Uh oh!

alyssawilk commented Feb 28, 2018

Uh oh!

cpakulski commented Feb 28, 2018

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ggreenway commented Mar 2, 2018

Uh oh!

cpakulski commented Mar 2, 2018

Uh oh!

junr03 commented Mar 5, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

lita commented Mar 5, 2018

Uh oh!

lita commented Mar 5, 2018

Uh oh!

lita commented Mar 5, 2018

Uh oh!

Uh oh!

junr03 commented Mar 5, 2018 •

edited

Loading