diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index fa62bc23f2de2..bc4859fe8ee1b 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -22,6 +22,8 @@ StandardLogger::StandardLogger(const std::string& name) : Logger(std::make_shared(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 diff --git a/source/common/common/logger.h b/source/common/common/logger.h index bbb6dc95eeb6c..01cdb398a4cb3 100644 --- a/source/common/common/logger.h +++ b/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 + 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)) { \ diff --git a/source/common/network/dns_impl.cc b/source/common/network/dns_impl.cc index 341f5400c3ccd..2063f49bcc6c1 100644 --- a/source/common/network/dns_impl.cc +++ b/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. diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index 62fe85f33e811..1f0daf063d7af 100644 --- a/test/common/common/logger_test.cc +++ b/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, 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