Add ENVOY_LOG_ONCE

source/common/common/logger.h

@@ -1,5 +1,6 @@
 #pragma once
 
+#include <chrono>
 #include <cstdint>
 #include <memory>
 #include <string>
@@ -400,6 +401,43 @@ template <Id id> class Loggable {
     }                                                                                              \
   } while (0)
 
+#define ENVOY_LOG_FIRST_N(LEVEL, N, ...)                                                           \
+  do {                                                                                             \
+    static auto* countdown = new std::atomic<uint64_t>();                                          \
+    if (countdown->fetch_add(1) < N) {                                                             \
+      ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                             \
+    }                                                                                              \
+  } while (0)
+
+#define ENVOY_LOG_ONCE(LEVEL, ...)                                                                 \
+  do {                                                                                             \
+    ENVOY_LOG_FIRST_N(LEVEL, 1, ##__VA_ARGS__);                                                    \
+  } while (0)
+
+#define ENVOY_LOG_EVERY_NTH(LEVEL, N, ...)                                                         \
+  do {                                                                                             \
+    static auto* count = new std::atomic<uint64_t>();                                              \
+    if ((count->fetch_add(1) % N) == 0) {                                                          \
+      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.
+// I think it's not easy to mock/simulate time here as it stands today anyway.
+using t_logclock = std::chrono::steady_clock; // NOLINT
+
+#define ENVOY_LOG_PERIODIC(LEVEL, CHRONO_DURATION, ...)                                            \
+  do {                                                                                             \
+    static auto* last_hit = new std::atomic<uint64_t>();                                           \
+    auto last = last_hit->load();                                                                  \
+    const auto now = t_logclock::now().time_since_epoch().count();                                 \
+    if ((now - last) >                                                                             \
+            std::chrono::duration_cast<std::chrono::nanoseconds>(CHRONO_DURATION).count() &&       \
+        last_hit->compare_exchange_strong(last, now)) {                                            \
+      ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                             \
+    }                                                                                              \
+  } while (0)
+
 #define ENVOY_FLUSH_LOG()                                                                          \
   do {                                                                                             \
     if (Envoy::Logger::Context::useFancyLogger()) {                                                \

test/common/common/log_macros_test.cc

@@ -1,3 +1,6 @@
+#include <chrono>
+#include <functional>
+#include <future>
 #include <iostream>
 #include <string>
 
@@ -13,6 +16,8 @@
 
 namespace Envoy {
 
+using namespace std::chrono_literals;
+
 class TestFilterLog : public Logger::Loggable<Logger::Id::filter> {
 public:
   void logMessage() {
@@ -118,6 +123,80 @@ TEST(Logger, checkLoggerLevel) {
   EXPECT_THAT(test_obj.executeAtTraceLevel(), testing::Eq(2));
 }
 
+void spamCall(std::function<void()>&& call_to_spam, const uint32_t num_threads) {
+  std::vector<std::thread> threads(num_threads);
+  std::promise<void> signal_all_threads_running;
+  std::shared_future<void> future(signal_all_threads_running.get_future());
+
+  for (auto& thread : threads) {
+    thread = std::thread([future, &call_to_spam] {
+      future.wait();
+      call_to_spam();
+    });
+  }
+  // Allow threads to accrue on future.wait() to maximize concurrency on the call
+  // we are testing.
+  sleep(1);
+  signal_all_threads_running.set_value();
+  for (std::thread& thread : threads) {
+    thread.join();
+  }
+}
+
+TEST(Logger, SparseLogMacros) {
+  class SparseLogMacrosTestHelper : public Logger::Loggable<Logger::Id::filter> {
+  public:
+    SparseLogMacrosTestHelper() { ENVOY_LOGGER().set_level(spdlog::level::info); }
+    void logSomething() { ENVOY_LOG_ONCE(error, "foo1 '{}'", evaluations()++); }
+    void logSomethingElse() { ENVOY_LOG_ONCE(error, "foo2 '{}'", evaluations()++); }
+    void logSomethingBelowLogLevelOnce() { ENVOY_LOG_ONCE(debug, "foo3 '{}'", evaluations()++); }
+    void logSomethingThrice() { ENVOY_LOG_FIRST_N(error, 3, "foo4 '{}'", evaluations()++); }
+    void logEverySeventh() { ENVOY_LOG_EVERY_NTH(error, 7, "foo5 '{}'", evaluations()++); }
+    void logEverySecond() { ENVOY_LOG_PERIODIC(error, 1s, "foo6 '{}'", evaluations()++); }
+    std::atomic<int32_t>& evaluations() { MUTABLE_CONSTRUCT_ON_FIRST_USE(std::atomic<int32_t>); };
+  };
+  constexpr uint32_t kNumThreads = 100;
+  SparseLogMacrosTestHelper helper;
+  spamCall(
+      [&helper]() {
+        helper.logSomething();
+        helper.logSomething();
+      },
+      kNumThreads);
+  EXPECT_EQ(1, helper.evaluations());
+  spamCall(
+      [&helper]() {
+        helper.logSomethingElse();
+        helper.logSomethingElse();
+      },
+      kNumThreads);
+  // Two distinct log lines ought to result in two evaluations, and no more.
+  EXPECT_EQ(2, helper.evaluations());
+
+  spamCall([&helper]() { helper.logSomethingThrice(); }, kNumThreads);
+  // Single log line should be emitted 3 times.
+  EXPECT_EQ(5, helper.evaluations());
+
+  spamCall([&helper]() { helper.logEverySeventh(); }, kNumThreads);
+  // (100 threads / log every 7th) + 1s = 15 more evaluations upon logging very 7th.
+  EXPECT_EQ(20, helper.evaluations());
+
+  // So use our knowledge that spamCall will sleep 1 second in the following lines:
+  // 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.
+  spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads);
+  EXPECT_EQ(21, helper.evaluations());
+  spamCall([&helper]() { helper.logEverySecond(); }, kNumThreads);
+  EXPECT_EQ(22, 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() ? 23 : 22, helper.evaluations());
+}
+
 TEST(RegistryTest, LoggerWithName) {
   EXPECT_EQ(nullptr, Logger::Registry::logger("blah"));
   EXPECT_EQ("upstream", Logger::Registry::logger("upstream")->name());