logger: macros evaluate logging level before invoking logger #2751

cpakulski · 2018-03-07T21:27:10Z

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. This addresses issue #2330. First PR #2676 was reverted because code did not compile when NVLOG compile flag was enabled. This has been fixed and test for this case has been added.

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. Added test to makes sure that code compiles when NVLOG is defined.

Docs Changes: N/A

Release Notes: N/A

…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>

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

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

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

If NVLOG is defined, trace and debug logging macros are evaluated to empty lines. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

htuch · 2018-03-07T21:29:54Z

@mrice32 sorry for the hot spotted load balancing here, but can you also look at this one as this is your code? Thanks.

cpakulski · 2018-03-07T21:30:09Z

@ggreenway @junr03 @lita @ccaraman Second PR attempt to address #2330. Corrected issue with NVLOG compile flag. The first PR was #2676 and was reverted.

mrice32

Looks good, thanks!

mrice32 · 2018-03-07T22:34:41Z

test/common/common/log_macros_test.cc

+  }
+}
+
+#ifdef NVLOG


Does the CI ever run in a mode with NVLOG defined? Put another way, will this test ever be executed by the CI or will it always be compiled out?

CI probably never runs with NVLOG defined. I invoked the test manually by running
bazel test --copt=-DNVLOG //test/common/common:log_macros_test

Should we set one of the circleCI jobs to define NVLOG? Maybe the "release" job?

That is probably good idea. I was surprised when my first PR #2676 was reverted even though it passed CI checks. If "release" CI job tests release image, it should probably use "release" compile flags.

Tracking here: #2754

@ggreenway I don't think we should do it on the release job because that job is used for building the docker images.

Not to throw a wrench in this, but I'm wondering with all the macros we have now and this change, if we should just kill NVLOG entirely. There is some perf benefit but now that the logs don't evaluate it's probably small.

I think all that would be needed is to add some type of macro/guard for the few places where we use NVLOG to block an expensive iteration. Thoughts?

Performance overhead is one function call and comparison between integers. Not much.
I just hope that trace and debug logs do not display sensitive information. With NVLOG they are just removed. If NVLOG is killed, all is required to display those logs is to lower severity level.

I think at this point I would vote to just kill NVLOG and replace with some additional macros for the places in which we use it for larger guards, but no objection to merging this PR.

@cpakulski are you interested in just getting rid of NVLOG as part of this PR?

mrice32

Two small nits - after that LGTM. Thanks for adding this! Sorry this has been so troublesome to get in, but I think it revealed some holes in our CI, which is awesome.

mrice32 · 2018-03-08T15:24:01Z

test/common/common/log_macros_test.cc

+
+#ifdef NVLOG
+TEST(Logger, doNotExpandTraceAndDebug) {
+  // The following two macros should not be expanded to no-op if NVLOG compile flag is defined.


nit: I realize that this is just a test to ensure they compile, but do we also want to add the incrementing counter behavior used above just to ensure the statements act as stated?

Done. Thanks for review and suggestions.

mrice32 · 2018-03-08T15:25:58Z

test/common/common/log_macros_test.cc

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


nit: same here as below, can we just add simple counter behavior above to ensure that this test not only compiles, but that it acts as expected?

alyssawilk

Looks great! Thanks for plugging away at this one :-)

alyssawilk · 2018-03-08T15:48:13Z

test/common/common/log_macros_test.cc

+TEST(Logger, doNotEvaluateParams) {
+  uint32_t i = 1;
+
+  // set logger's logging level high and log a message with lower severity


Super nitty, mind set ->Set here and above and do -> Do on 69?

Thanks for catching it. It has been corrected.

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

mrice32 · 2018-03-08T19:08:12Z

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


nit: prefer EXPECT* for non-fatal failures, since ASSERT* will essentially abort the test case. Here and elsewhere.

Good suggestion. Done.

Testing will continue even when one test fails. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

mrice32

LGTM, thanks!

cpakulski · 2018-03-08T21:41:03Z

If there are any other comments related to this PR, they will have to wait - I will be away for few days.

cpakulski · 2018-03-10T12:13:39Z

@mattklein123 sure - I can remove NVLOG. I am away though for few days. On Mar 9, 2018 3:02 PM, "Matt Klein" <notifications@github.com> wrote: *@mattklein123* commented on this pull request. ------------------------------ In test/common/common/log_macros_test.cc <#2751 (comment)>:

+ // 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"); + } +} + +#ifdef NVLOG @cpakulski <https://github.com/cpakulski> are you interested in just getting rid of NVLOG as part of this PR? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#2751 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/Aiy1DlAGE75oMLso-SxQK4fL8OfJ_oSdks5tct-_gaJpZM4ShLzL> .

mattklein123 · 2018-03-10T22:54:56Z

@cpakulski no problem, take your time. Thank you!

mattklein123 · 2018-03-16T19:51:11Z

Per new release note policy please add a release note with any applicable feature docs to https://github.com/envoyproxy/data-plane-api/blob/master/docs/root/intro/version_history.rst. Thank you!

cpakulski · 2018-03-20T15:22:22Z

@mattklein123 @ggreenway I would prefer to remove NVLOG flag as a separate PR. My main concern is that if for any reason (performance for example) those changes have to be removed, it will be easier to revert. If you agree, please merge this PR #2751 and open a new issue to track removal of NVLOG flag.

mattklein123 · 2018-03-20T16:37:40Z

@cpakulski sure, that's fine. I opened #2854 to track.

@alyssawilk

…g levels. (envoyproxy#2984)" This reverts commit 4874315. As pointed out by @alyssawilk, this doesn't make sense given envoyproxy#2751. I think the profile that motivated this must have been created before the Google import included envoyproxy#2751. Signed-off-by: Harvey Tuch <htuch@google.com>

@alyssawilk

…g levels. (#2984)" (#3054) This reverts commit 4874315. As pointed out by @alyssawilk, this doesn't make sense given #2751. I think the profile that motivated this must have been created before the Google import included #2751. Signed-off-by: Harvey Tuch <htuch@google.com>

cpakulski added 5 commits February 26, 2018 16:28

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>

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>

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

ef37d67

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

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>

Modified logging macros to accomodate NVLOG compile flag.

4641d74

If NVLOG is defined, trace and debug logging macros are evaluated to empty lines. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

htuch assigned mrice32 and alyssawilk Mar 7, 2018

mrice32 reviewed Mar 7, 2018

View reviewed changes

mrice32 reviewed Mar 8, 2018

View reviewed changes

alyssawilk reviewed Mar 8, 2018

View reviewed changes

Improved LOGGER unit tests.

852538a

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

mrice32 reviewed Mar 8, 2018

View reviewed changes

cpakulski added 2 commits March 8, 2018 14:19

Changed all ASSERT_THAT calls to EXPECT_THAT.

8e15dd3

Testing will continue even when one test fails. Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

Corrected spelling in few comments.

e4dc3af

Signed-off-by: Christoph Pakulski <paker8848@gmail.com>

mrice32 approved these changes Mar 8, 2018

View reviewed changes

mattklein123 mentioned this pull request Mar 15, 2018

Make one of the CI jobs define NVLOG #2754

Closed

mattklein123 mentioned this pull request Mar 19, 2018

upstream: log metadata used to create subset lbs #2772

Merged

mattklein123 mentioned this pull request Mar 20, 2018

Remove NVLOG compile define #2854

Closed

mattklein123 approved these changes Mar 20, 2018

View reviewed changes

alyssawilk approved these changes Mar 20, 2018

View reviewed changes

mattklein123 merged commit f45b785 into envoyproxy:master Mar 20, 2018

cpakulski mentioned this pull request Mar 23, 2018

logger: removed NVLOG compile flag #2886

Merged

mattklein123 mentioned this pull request Apr 6, 2018

loss of coverage of logging paths #3012

Closed

htuch mentioned this pull request Apr 11, 2018

Revert "config: optimize RepeatedPtrUtil::debugString at non-debug lo… #3054

Merged

cpakulski mentioned this pull request Apr 12, 2018

coverage report: lower log level to trace and drop all logs #3065

Merged

cpakulski deleted the issue/2330 branch May 1, 2018 13:22

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logger: macros evaluate logging level before invoking logger #2751

logger: macros evaluate logging level before invoking logger #2751

cpakulski commented Mar 7, 2018

htuch commented Mar 7, 2018

cpakulski commented Mar 7, 2018

mrice32 left a comment

mrice32 Mar 7, 2018

cpakulski Mar 7, 2018 •

edited

Loading

ggreenway Mar 7, 2018

cpakulski Mar 7, 2018

ggreenway Mar 7, 2018

mattklein123 Mar 8, 2018

cpakulski Mar 8, 2018

mattklein123 Mar 8, 2018

mrice32 Mar 9, 2018

mattklein123 Mar 9, 2018

mrice32 left a comment

mrice32 Mar 8, 2018

cpakulski Mar 8, 2018

mrice32 Mar 8, 2018

cpakulski Mar 8, 2018

alyssawilk left a comment

alyssawilk Mar 8, 2018

cpakulski Mar 8, 2018

mrice32 Mar 8, 2018 •

edited

Loading

cpakulski Mar 8, 2018

mrice32 left a comment

cpakulski commented Mar 8, 2018

cpakulski commented Mar 10, 2018 via email

mattklein123 commented Mar 10, 2018

mattklein123 commented Mar 16, 2018

cpakulski commented Mar 20, 2018

mattklein123 commented Mar 20, 2018

logger: macros evaluate logging level before invoking logger #2751

logger: macros evaluate logging level before invoking logger #2751

Conversation

cpakulski commented Mar 7, 2018

htuch commented Mar 7, 2018

cpakulski commented Mar 7, 2018

mrice32 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

cpakulski Mar 7, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mrice32 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

alyssawilk left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mrice32 Mar 8, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mrice32 left a comment

Choose a reason for hiding this comment

cpakulski commented Mar 8, 2018

cpakulski commented Mar 10, 2018 via email

mattklein123 commented Mar 10, 2018

mattklein123 commented Mar 16, 2018

cpakulski commented Mar 20, 2018

mattklein123 commented Mar 20, 2018

cpakulski Mar 7, 2018 •

edited

Loading

mrice32 Mar 8, 2018 •

edited

Loading