Add ENVOY_LOG_ONCE by oschaaf · Pull Request #12830 · envoyproxy/envoy

oschaaf · 2020-08-26T20:30:54Z

Sometimes there's error flow control in the hot path that deserves logging,
but plain logging there risks generating a large amount of log spam.
It would be great to have a low-barrier and easy-to-consume way to emit a single
or bounded number of log lines in these cases. This proposes a means to emit
a single log line in those cases.

Cross referencing Nighthawk issue to prompted this:
envoyproxy/nighthawk#484

Signed-off-by: Otto van der Schaaf oschaaf@we-amp.com

Risk Level: Low
Testing: Unit test

Sometimes there's error flow control in the hot path that deserves logging, but plain logging there risks generating a large amount of log spam. It would be great to have a low-barrier and easy-to-consume way to emit a single or bounded number of log lines in these cases. This proposes a means to emit a single log line in those cases. Cross referencing Nighthawk issue to prompted this: envoyproxy/nighthawk#484 Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf · 2020-08-26T20:31:01Z

/assign htuch

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

ggreenway · 2020-08-26T22:49:46Z

Instead of once, what about the strategy used in ENVOY_BUG, which IIRC takes an action on powers of two counts of the event occurring, which results in exponential backoff. It gives more signal about whether something really only happened once, or is happening repeatedly.

oschaaf · 2020-08-27T09:41:23Z

@ggreenway Thanks for the feedback; I should first get this simplest of cases to work, because CI indicates something isn't right. Having said that, and assuming I can fix that using the current approach: with respect to logging, I wonder if there's a silver bullet. Maybe we should consider offering a series so one can choose the best one? Some variants that I can think of:

log once and never again (e.g. )
log every nth occurrence, maybe append number of actual occurrences to the log message
log at most once per period, maybe append the actual rate to the log message

and then maybe have flags or macro variants that set things up to configure strictness of the log gating of these macros;
it might be possible to trade in precision for performance (at the extreme just use thread local state).
I recon this last part could perhaps be useful for certain types of debug level logging in hot paths.

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf · 2020-08-27T12:30:38Z

I had to amend the expected number of argument evaluations in the test for when fine grained logging is enabled / FANCY_LOG is used: when enabled, ENVOY_LOG will evaluate arguments regardless of the configured log level, whereas without the feature enabled, it will only evaluate when the log level filter doesn't squelch the message.

I think that with 63b8a08 this will pass CI, but isn't it kind of tricky to have the argument evaluation behaviour change based on a flag? (because of potential side effects?)

htuch · 2020-08-27T18:47:08Z

I think we don't want to evaluate ENVOY_LOG arguments if the log level doesn't match, this seems a bug in the fancy logger.

htuch · 2020-08-28T21:32:55Z

@oschaaf can you file a bug and attach a TODO for fancy logger?

Looking at how we use this kind of macro, how about a small modification to make this a bit more general and make this ENVOY_LOG_FIRST_N where it logs the first N times.

…oposal

Periodic isn't perfect, as it reference a real-world time source directly. Depending on feedback / if it's a lot of work to do this right, it can be backed out for now. Will need a follow up with more tests for the new macros. Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf · 2020-08-29T18:39:04Z

@htuch Added ENVOY_LOG_FIRST_N, ENVOY_LOG_EVERY_NTH, ENVOY_LOG_PERIODIC in 2d47780
The periodic version references a real-world time source directly though.
Depending on feedback / if it's a lot of work to do that right I can back that one out.

Regardless, to take this foward, I will need another follow to add more tests. But I'm curious to hear your thoughts on
so far.

ps: rebuilding Envoy takes a while when touching logging.h, a fast & easy means to toy around with the code resides here: https://gist.github.com/oschaaf/4113ac357d7537a470c09c1f2285d731

oschaaf · 2020-08-29T18:46:30Z

Filed #12885 for the FANCY_LOG variadic macro evaluation issue observed here.

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

htuch · 2020-08-31T13:10:21Z

test/common/common/log_macros_test.cc

+  }
+  // Allow threads to accrue on future.wait() to maximize concurrency on the call
+  // we are testing.
+  sleep(1);


I think we want to avoid relying on real-time for tests. @jmarantz do you see a way to cleanly add an injected time source for the periodic macro that @oschaaf introduced in this PR? I'm thinking maybe we need a time source singleton for logging and do singleton injection, to avoid having to worry about time source at call site.

In 371fa5d I rewrote the test to not rely on sleep().
Also backed out ENVOY_LOG_PERIODIC with the intent to do a follow up for adding that after this.
(so we can take a look and discuss that separately)

htuch · 2020-08-31T13:14:10Z

source/common/common/logger.h

+    ENVOY_LOG_FIRST_N(LEVEL, 1, ##__VA_ARGS__);                                                    \
+  } while (0)
+
+#define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...)                                                         \


As per earlier discussion, every Pow2 could be good as well.

Oh yes good catch, my intent was actually to add that. Will do.

Done, added ENVOY_LOG_WITH_BACKOFF in 371fa5d + tests

/cc @ggreenway ^^

- Back out controversial ENVOY_LOG_PERIODIC, will split that out. - Don't rely on sleep() in tests - Add ENVOY_LOG_WITH_BACKOFF Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

htuch

LGTM modulo comments.
/wait

htuch · 2020-09-01T18:07:10Z

source/common/common/logger.h

+    }                                                                                              \
+  } while (0)
+
+#define ENVOY_LOG_WITH_BACKOFF(LEVEL, ...)                                                         \


Nit: ENVOY_LOG_EVERY_POW_2 (more consistent with some internal terminology and clearer what backoff means).

Done in de23f2a

htuch · 2020-09-01T20:22:02Z

test/common/common/log_macros_test.cc

+  }
+  // Allow threads to accrue on future.wait() to maximize concurrency on the call
+  // we are testing.
+  while (runcount != num_threads) {


What about something like https://abseil.io/docs/cpp/guides/synchronization#barrier?

Ooh, that's awesome. Switched to use absl::Barrier in de23f2a

- Use absl::Barrier - Rename ENVOY_LOG_WITH_BACKOFF to ENVOY_LOG_EVERY_POW_2 Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

…oposal Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf · 2020-09-02T00:25:05Z

Coverage flaked on an unrelated issue
/retest

repokitteh-read-only · 2020-09-02T00:25:08Z

Retrying Azure Pipelines, to retry CircleCI checks, use /retest-circle.
Cannot retry non-completed check: envoy-presubmit (Linux-x64 compile_time_options), please wait.

🐱

Caused by: a #12830 (comment) was created by @oschaaf.

see: more, trace.

oschaaf · 2020-09-02T10:10:16Z

/retest

repokitteh-read-only · 2020-09-02T10:10:21Z

Retrying Azure Pipelines, to retry CircleCI checks, use /retest-circle.
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #12830 (comment) was created by @oschaaf.

see: more, trace.

ggreenway

Other than sorting out the thread-safety of static variables, I like this a lot.

ggreenway · 2020-09-02T18:27:13Z

source/common/common/logger.h


+#define ENVOY_LOG_FIRST_N(LEVEL, N, ...)                                                           \
+  do {                                                                                             \
+    static auto* countdown = new std::atomic<uint64_t>();                                          \


This isn't thread-safe. If two threads do this at the same time, there could be a leak. I think this ends up being better as static std::atomic<uint64_t> countdown;. Either the compiler will see that it is initialized by zeroing, and do so at program start, or it will double-zero the same memory by initializing multiple times, but should avoid a leak at least.

Wouldn't that lead up to a potential deinitialization fiasco? I was following the lead of

envoy/source/common/common/macros.h

Line 32 in f2306b3

#define CONSTRUCT_ON_FIRST_USE(type, ...) \

Reading up I am led to believe this would be thread safe since c++ 11 but I can't find a source that I would consider authorative,. Will dig some more.

Relevant on the subject of leaking and stack vs heap allocation in the construct on first use idiom: Why doesn’t the Construct On First Use Idiom use a static object instead of a static pointer?

https://en.cppreference.com/w/cpp/language/storage_duration#Static_local_variables has:

If multiple threads attempt to initialize the same static local variable concurrently, the initialization occurs exactly once (similar behavior can be obtained for arbitrary functions with std::call_once). Note: usual implementations of this feature use variants of the double-checked locking pattern, which reduces runtime overhead for already-initialized local statics to a single non-atomic boolean comparison.

Did some reading, and you're correct. TIL something new about static initialization.

ggreenway · 2020-09-02T18:31:23Z

/wait

Concerns were addressed.

Follow up to envoyproxy#12830 with another sparse log variant. The periodic version relies on a real world time source, which can be discussed separately here. Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Follow up to #12830 with another sparse log variant. The periodic version relies on a real world time source, which can be discussed separately here. Risk Level: Low Testing: Unit tests Signed-off-by: Otto van der Schaaf oschaaf@we-amp.com

repokitteh-read-only bot assigned htuch Aug 26, 2020

oschaaf mentioned this pull request Aug 26, 2020

Avoiding high frequency logging envoyproxy/nighthawk#484

Closed

Style: fix variable name

6770737

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf added 2 commits August 27, 2020 11:48

Explicitly set log level, as it may diverage accross CI tasks

72829d5

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Fine grained logging evaluates regardless of log level

63b8a08

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf added 2 commits August 29, 2020 19:13

Merge remote-tracking branch 'upstream/master' into envoy-log-once-pr…

9e29f4a

…oposal

oschaaf mentioned this pull request Aug 29, 2020

Fine grained logging via FANCY_LOG always evaluates macro arguments #12885

Open

oschaaf added 4 commits August 30, 2020 14:15

Add threaded log macro spam tests pt I.

99e9686

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Test all macro variants

d8a6304

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

tsan: atomically increment evaluations in SparseLogMacrosTestHelper.

aa67ebb

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Fix ENVOY_LOG_PERIODIC gcc build: use trivial type for std::atomic.

d8783b7

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

htuch reviewed Aug 31, 2020

View reviewed changes

oschaaf added 3 commits August 31, 2020 16:57

Review feedback.

371fa5d

- Back out controversial ENVOY_LOG_PERIODIC, will split that out. - Don't rely on sleep() in tests - Add ENVOY_LOG_WITH_BACKOFF Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Remove superfluous line.

9480137

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Use std::bitset instead of builtin

09ff427

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

htuch assigned ggreenway Sep 1, 2020

htuch requested a review from ggreenway September 1, 2020 18:04

htuch previously requested changes Sep 1, 2020

View reviewed changes

repokitteh-read-only bot added the waiting label Sep 1, 2020

oschaaf added 2 commits September 1, 2020 22:42

Review feedback

de23f2a

- Use absl::Barrier - Rename ENVOY_LOG_WITH_BACKOFF to ENVOY_LOG_EVERY_POW_2 Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Merge remote-tracking branch 'upstream/master' into envoy-log-once-pr…

53d5cc1

…oposal Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

repokitteh-read-only bot removed the waiting label Sep 1, 2020

oschaaf added 2 commits September 2, 2020 00:07

Address clang-tidy complaint (hopefully)

2ab747d

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

clang-tidy: Use smart pointer with absl::Barrier

536300e

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

ggreenway requested changes Sep 2, 2020

View reviewed changes

repokitteh-read-only bot added the waiting label Sep 2, 2020

ggreenway approved these changes Sep 2, 2020

View reviewed changes

ggreenway merged commit f1c0031 into envoyproxy:master Sep 2, 2020

oschaaf mentioned this pull request Sep 2, 2020

Add ENVOY_LOG_PERIODIC #12961

Merged

Conversation

oschaaf commented Aug 26, 2020

Uh oh!

oschaaf commented Aug 26, 2020

Uh oh!

ggreenway commented Aug 26, 2020

Uh oh!

oschaaf commented Aug 27, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

oschaaf commented Aug 27, 2020

Uh oh!

htuch commented Aug 27, 2020

Uh oh!

htuch commented Aug 28, 2020

Uh oh!

oschaaf commented Aug 29, 2020

Uh oh!

oschaaf commented Aug 29, 2020

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!

Choose a reason for hiding this comment

Uh oh!

htuch 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!

oschaaf commented Sep 2, 2020

Uh oh!

repokitteh-read-only bot commented Sep 2, 2020

Uh oh!

oschaaf commented Sep 2, 2020

Uh oh!

repokitteh-read-only bot commented Sep 2, 2020

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!

ggreenway commented Sep 2, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

oschaaf commented Aug 27, 2020 •

edited

Loading