diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 8e1bed6412420..f30dd283e99c1 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -1,6 +1,7 @@ #pragma once #include +#include #include #include #include @@ -403,9 +404,11 @@ template class Loggable { #define ENVOY_LOG_FIRST_N(LEVEL, N, ...) \ do { \ - static auto* countdown = new std::atomic(); \ - if (countdown->fetch_add(1) < N) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* countdown = new std::atomic(); \ + if (countdown->fetch_add(1) < N) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ } \ } while (0) @@ -416,17 +419,40 @@ template class Loggable { #define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...) \ do { \ - static auto* count = new std::atomic(); \ - if ((count->fetch_add(1) % N) == 0) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* count = new std::atomic(); \ + if ((count->fetch_add(1) % N) == 0) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ } \ } while (0) #define ENVOY_LOG_EVERY_POW_2(LEVEL, ...) \ do { \ - static auto* count = new std::atomic(); \ - if (std::bitset<64>(1 + count->fetch_add(1)).count() == 1) { \ - ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* count = new std::atomic(); \ + if (std::bitset<64>(1 /* for the first hit*/ + count->fetch_add(1)).count() == 1) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ + } \ + } while (0) + +// This is to get us to pass the format check. We reference a real-world time source here. +// We'd have to introduce a singleton for a time source here, and consensus was that avoiding +// that is preferable. +using t_logclock = std::chrono::steady_clock; // NOLINT + +#define ENVOY_LOG_PERIODIC(LEVEL, CHRONO_DURATION, ...) \ + do { \ + if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) { \ + static auto* last_hit = new std::atomic(); \ + auto last = last_hit->load(); \ + const auto now = t_logclock::now().time_since_epoch().count(); \ + if ((now - last) > \ + std::chrono::duration_cast(CHRONO_DURATION).count() && \ + last_hit->compare_exchange_strong(last, now)) { \ + ENVOY_LOG(LEVEL, ##__VA_ARGS__); \ + } \ } \ } while (0) diff --git a/test/common/common/log_macros_test.cc b/test/common/common/log_macros_test.cc index 84a2cd79b4961..5625a5f570567 100644 --- a/test/common/common/log_macros_test.cc +++ b/test/common/common/log_macros_test.cc @@ -1,6 +1,8 @@ +#include #include #include #include +#include #include "common/common/fancy_logger.h" #include "common/common/logger.h" @@ -15,6 +17,8 @@ namespace Envoy { +using namespace std::chrono_literals; + class TestFilterLog : public Logger::Loggable { public: void logMessage() { @@ -148,6 +152,7 @@ TEST(Logger, SparseLogMacros) { void logSomethingThrice() { ENVOY_LOG_FIRST_N(error, 3, "foo4 '{}'", evaluations()++); } void logEverySeventh() { ENVOY_LOG_EVERY_NTH(error, 7, "foo5 '{}'", evaluations()++); } void logEveryPow2() { ENVOY_LOG_EVERY_POW_2(error, "foo6 '{}'", evaluations()++); } + void logEverySecond() { ENVOY_LOG_PERIODIC(error, 1s, "foo7 '{}'", evaluations()++); } std::atomic& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic); }; }; constexpr uint32_t kNumThreads = 100; @@ -185,11 +190,21 @@ TEST(Logger, SparseLogMacros) { // We should log on 2, 4, 8, 16, 32, 64, which means we can expect to add 6 more evaluations. EXPECT_EQ(27, helper.evaluations()); + spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads); + // First call ought to evaluate. + EXPECT_EQ(28, helper.evaluations()); + + // We expect one log entry / second. Therefore each spamCall ought to result in one + // more evaluation. This depends on real time and not sim time, hopefully 1 second + // is enough to not introduce flakes in practice. + std::this_thread::sleep_for(1s); // NOLINT + spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads); + EXPECT_EQ(29, helper.evaluations()); + spamCall([&helper]() { helper.logSomethingBelowLogLevelOnce(); }, kNumThreads); - // Without fine-grained logging, we shouldn't observe additional argument evaluations - // for log lines below the configured log level. - // TODO(#12885): fancy logger shouldn't always evaluate variadic macro arguments. - EXPECT_EQ(::Envoy::Logger::Context::useFancyLogger() ? 28 : 27, helper.evaluations()); + // We shouldn't observe additional argument evaluations for log lines below the configured + // log level. + EXPECT_EQ(29, helper.evaluations()); } TEST(RegistryTest, LoggerWithName) { diff --git a/tools/code_format/check_format.py b/tools/code_format/check_format.py index 5ac0e628bdcc3..3bd79a37f7276 100755 --- a/tools/code_format/check_format.py +++ b/tools/code_format/check_format.py @@ -37,6 +37,7 @@ "./source/common/event/real_time_system.h", "./source/exe/main_common.cc", "./source/exe/main_common.h", "./source/server/config_validation/server.cc", "./source/common/common/perf_annotation.h", + "./test/common/common/log_macros_test.cc", "./test/test_common/simulated_time_system.cc", "./test/test_common/simulated_time_system.h", "./test/test_common/test_time.cc", "./test/test_common/test_time.h",