common: introduce stable logger /w examples in DNS

source/common/common/logger.cc

@@ -22,6 +22,8 @@ StandardLogger::StandardLogger(const std::string& name)
     : Logger(std::make_shared<spdlog::logger>(name, Registry::getSink())) {}
 
 SinkDelegate::SinkDelegate(DelegatingLogSinkSharedPtr log_sink) : log_sink_(log_sink) {}
+void SinkDelegate::logWithStableName(absl::string_view, absl::string_view, absl::string_view,
+                                     absl::string_view) {}
 
 SinkDelegate::~SinkDelegate() {
   // The previous delegate should have never been set or should have been reset by now via

source/common/common/logger.h

@@ -107,6 +107,8 @@ class SinkDelegate : NonCopyable {
   virtual ~SinkDelegate();
 
   virtual void log(absl::string_view msg) PURE;
+  virtual void logWithStableName(absl::string_view stable_name, absl::string_view level,
+                                 absl::string_view component, absl::string_view msg);
   virtual void flush() PURE;
 
 protected:
@@ -157,6 +159,12 @@ class DelegatingLogSink : public spdlog::sinks::sink {
   void setLock(Thread::BasicLockable& lock) { stderr_sink_->setLock(lock); }
   void clearLock() { stderr_sink_->clearLock(); }
 
+  template <class... Args>
+  void logWithStableName(absl::string_view stable_name, absl::string_view level,
+                         absl::string_view component, Args... msg) {
+    absl::ReaderMutexLock sink_lock(&sink_mutex_);
+    sink_->logWithStableName(stable_name, level, component, fmt::format(msg...));
+  }
   // spdlog::sinks::sink
   void log(const spdlog::details::log_msg& msg) override;
   void flush() override {
@@ -445,6 +453,26 @@ class EscapeMessageJsonString : public spdlog::custom_flag_formatter {
  */
 #define ENVOY_LOG(LEVEL, ...) ENVOY_LOG_TO_LOGGER(ENVOY_LOGGER(), LEVEL, ##__VA_ARGS__)
 
+/**
+ * Log with a stable event name. This allows emitting a log line with a stable name in addition to
+ * the standard log line. The stable log line is passed to custom sinks that may want to intercept
+ * these log messages.
+ *
+ * By default these named logs are not handled, but a custom log sink may intercept them by
+ * implementing the logWithStableName function.
+ */
+#define ENVOY_LOG_EVENT(LEVEL, EVENT_NAME, ...)                                                    \
+  ENVOY_LOG_EVENT_TO_LOGGER(ENVOY_LOGGER(), LEVEL, EVENT_NAME, ##__VA_ARGS__)
+
+#define ENVOY_LOG_EVENT_TO_LOGGER(LOGGER, LEVEL, EVENT_NAME, ...)                                  \
+  do {                                                                                             \
+    ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                               \
+    if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) {                                                     \
+      ::Envoy::Logger::Registry::getSink()->logWithStableName(EVENT_NAME, #LEVEL, (LOGGER).name(), \
+                                                              ##__VA_ARGS__);                      \
+    }                                                                                              \
+  } while (0)
+
 #define ENVOY_LOG_FIRST_N_TO_LOGGER(LOGGER, LEVEL, N, ...)                                         \
   do {                                                                                             \
     if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) {                                                     \

source/common/network/dns_impl.cc

@@ -105,6 +105,9 @@ void DnsResolverImpl::PendingResolution::onAresGetAddrInfoCallback(int status, i
     // callback_ target _should_ still be around. In that case, raise the callback_ so the target
     // can be done with this query and initiate a new one.
     if (!cancelled_) {
+      ENVOY_LOG_EVENT(debug, "dns_resolution_destroyed", "dns resolution for {} destroyed",
+                      dns_name_);
+
       callback_(ResolutionStatus::Failure, {});
     }
     delete this;
@@ -180,6 +183,10 @@ void DnsResolverImpl::PendingResolution::onAresGetAddrInfoCallback(int status, i
       // portFromTcpUrl().
       // TODO(chaoqin-li1123): remove try catch pattern here once we figure how to handle unexpected
       // exception in fuzz tests.
+      ENVOY_LOG_EVENT(debug, "dns_resolution_complete",
+                      "dns resolution for {} completed with status {}", dns_name_,
+                      resolution_status);
+
       TRY_NEEDS_AUDIT { callback_(resolution_status, std::move(address_list)); }
       catch (const EnvoyException& e) {
         ENVOY_LOG(critical, "EnvoyException in c-ares callback: {}", e.what());
@@ -253,6 +260,8 @@ void DnsResolverImpl::onAresSocketStateChange(os_fd_t fd, int read, int write) {
 
 ActiveDnsQuery* DnsResolverImpl::resolve(const std::string& dns_name,
                                          DnsLookupFamily dns_lookup_family, ResolveCb callback) {
+  ENVOY_LOG_EVENT(debug, "cares_dns_resolution_started", "dns resolution for {} started", dns_name);
+
   // TODO(hennna): Add DNS caching which will allow testing the edge case of a
   // failed initial call to getAddrInfo followed by a synchronous IPv4
   // resolution.

test/common/common/logger_test.cc

@@ -9,6 +9,8 @@
 #include "gmock/gmock.h"
 #include "gtest/gtest.h"
 
+using testing::_;
+
 namespace Envoy {
 namespace Logger {
 
@@ -151,5 +153,31 @@ TEST_F(LoggerCustomFlagsTest, LogMessageAsJsonStringEscaped) {
       "\\\"transport: Error while dialing dial tcp [::1]:15012: connect: connection refused\\\"");
 }
 
+struct NamedLogSink : SinkDelegate {
+  NamedLogSink(DelegatingLogSinkSharedPtr log_sink) : SinkDelegate(log_sink) { setDelegate(); }
+  ~NamedLogSink() override { restoreDelegate(); }
+
+  MOCK_METHOD(void, log, (absl::string_view));
+  MOCK_METHOD(void, logWithStableName,
+              (absl::string_view, absl::string_view, absl::string_view, absl::string_view));
+  void flush() override {}
+};
+
+class NamedLogTest : public Loggable<Id::assert>, public testing::Test {};
+
+TEST_F(NamedLogTest, NamedLogsAreSentToSink) {
+  NamedLogSink sink(Envoy::Logger::Registry::getSink());
+
+  Envoy::Logger::Registry::setLogLevel(spdlog::level::info);
+  // Log level is above debug, so we shouldn't get any logs.
+  ENVOY_LOG_EVENT(debug, "test_event", "not logged");
+
+  Envoy::Logger::Registry::setLogLevel(spdlog::level::debug);
+
+  EXPECT_CALL(sink, log(_));
+  EXPECT_CALL(sink, logWithStableName("test_event", "debug", "assert", "test log 1"));
+  ENVOY_LOG_EVENT(debug, "test_event", "test {} {}", "log", 1);
+}
+
 } // namespace Logger
 } // namespace Envoy