diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index bc4859fe8ee1b..ec0e4a99a5c63 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -27,8 +27,15 @@ void SinkDelegate::logWithStableName(absl::string_view, absl::string_view, absl: SinkDelegate::~SinkDelegate() { // The previous delegate should have never been set or should have been reset by now via - // restoreDelegate(); + // restoreDelegate()/restoreTlsDelegate(); assert(previous_delegate_ == nullptr); + assert(previous_tls_delegate_ == nullptr); +} + +void SinkDelegate::setTlsDelegate() { + assert(previous_tls_delegate_ == nullptr); + previous_tls_delegate_ = log_sink_->tlsDelegate(); + log_sink_->setTlsDelegate(this); } void SinkDelegate::setDelegate() { @@ -38,6 +45,13 @@ void SinkDelegate::setDelegate() { log_sink_->setDelegate(this); } +void SinkDelegate::restoreTlsDelegate() { + // Ensures stacked allocation of delegates. + assert(log_sink_->tlsDelegate() == this); + log_sink_->setTlsDelegate(previous_tls_delegate_); + previous_tls_delegate_ = nullptr; +} + void SinkDelegate::restoreDelegate() { // Ensures stacked allocation of delegates. assert(log_sink_->delegate() == this); @@ -80,6 +94,19 @@ void DelegatingLogSink::log(const spdlog::details::log_msg& msg) { } lock.Release(); + auto log_to_sink = [this, msg_view](SinkDelegate& sink) { + if (should_escape_) { + sink.log(escapeLogLine(msg_view)); + } else { + sink.log(msg_view); + } + }; + auto* tls_sink = tlsDelegate(); + if (tls_sink != nullptr) { + log_to_sink(*tls_sink); + return; + } + // Hold the sink mutex while performing the actual logging. This prevents the sink from being // swapped during an individual log event. // TODO(mattklein123): In production this lock will never be contended. In practice, thread @@ -87,11 +114,7 @@ void DelegatingLogSink::log(const spdlog::details::log_msg& msg) { // mechanism for this that does not require extra locking that we don't explicitly need in the // prod code. absl::ReaderMutexLock sink_lock(&sink_mutex_); - if (should_escape_) { - sink_->log(escapeLogLine(msg_view)); - } else { - sink_->log(msg_view); - } + log_to_sink(*sink_); } std::string DelegatingLogSink::escapeLogLine(absl::string_view msg_view) { @@ -111,6 +134,26 @@ DelegatingLogSinkSharedPtr DelegatingLogSink::init() { return delegating_sink; } +void DelegatingLogSink::flush() { + auto* tls_sink = tlsDelegate(); + if (tls_sink != nullptr) { + tls_sink->flush(); + return; + } + absl::ReaderMutexLock lock(&sink_mutex_); + sink_->flush(); +} + +SinkDelegate** DelegatingLogSink::tlsSink() { + static thread_local SinkDelegate* tls_sink = nullptr; + + return &tls_sink; +} + +void DelegatingLogSink::setTlsDelegate(SinkDelegate* sink) { *tlsSink() = sink; } + +SinkDelegate* DelegatingLogSink::tlsDelegate() { return *tlsSink(); } + static Context* current_context = nullptr; Context::Context(spdlog::level::level_enum log_level, const std::string& log_format, diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 73425c4c827a5..2dd45c7e8daaa 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -115,21 +115,30 @@ class SinkDelegate : NonCopyable { virtual void flush() PURE; protected: - // Swap the current log sink delegate for this one. This should be called by the derived class - // constructor immediately before returning. This is required to match restoreDelegate(), - // otherwise it's possible for the previous delegate to get set in the base class constructor, - // the derived class constructor throws, and cleanup becomes broken. + // Swap the current thread local log sink delegate for this one. This should be called by the + // derived class constructor immediately before returning. This is required to match + // restoreTlsDelegate(), otherwise it's possible for the previous delegate to get set in the base + // class constructor, the derived class constructor throws, and cleanup becomes broken. + void setTlsDelegate(); + + // Swap the current *global* log sink delegate for this one. This behaves as setTlsDelegate, but + // operates on the global log sink instead of the thread local one. void setDelegate(); - // Swap the current log sink (this) for the previous one. This should be called by the derived - // class destructor in the body. This is critical as otherwise it's possible for a log message - // to get routed to a partially destructed sink. + // Swap the current thread local log sink (this) for the previous one. This should be called by + // the derived class destructor in the body. This is critical as otherwise it's possible for a log + // message to get routed to a partially destructed sink. + void restoreTlsDelegate(); + + // Swap the current *global* log sink delegate for the previous one. This behaves as + // restoreTlsDelegate, but operates on the global sink instead of the thread local one. void restoreDelegate(); SinkDelegate* previousDelegate() { return previous_delegate_; } private: SinkDelegate* previous_delegate_{nullptr}; + SinkDelegate* previous_tls_delegate_{nullptr}; DelegatingLogSinkSharedPtr log_sink_; }; @@ -165,15 +174,17 @@ class DelegatingLogSink : public spdlog::sinks::sink { template void logWithStableName(absl::string_view stable_name, absl::string_view level, absl::string_view component, Args... msg) { + auto tls_sink = tlsDelegate(); + if (tls_sink != nullptr) { + tls_sink->logWithStableName(stable_name, level, component, fmt::format(msg...)); + return; + } 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 { - absl::ReaderMutexLock lock(&sink_mutex_); - sink_->flush(); - } + void flush() override; void set_pattern(const std::string& pattern) override { set_formatter(spdlog::details::make_unique(pattern)); } @@ -220,6 +231,9 @@ class DelegatingLogSink : public spdlog::sinks::sink { absl::ReaderMutexLock lock(&sink_mutex_); return sink_; } + SinkDelegate** tlsSink(); + void setTlsDelegate(SinkDelegate* sink); + SinkDelegate* tlsDelegate(); SinkDelegate* sink_ ABSL_GUARDED_BY(sink_mutex_){nullptr}; absl::Mutex sink_mutex_; diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index ba0578abaecf4..d1ecf385ba95a 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -185,5 +185,49 @@ TEST_F(NamedLogTest, NamedLogsAreSentToSink) { ENVOY_LOG_EVENT_TO_LOGGER(Registry::getLog(Id::misc), debug, "misc_event", "log"); } +struct TlsLogSink : SinkDelegate { + TlsLogSink(DelegatingLogSinkSharedPtr log_sink) : SinkDelegate(log_sink) { setTlsDelegate(); } + ~TlsLogSink() override { restoreTlsDelegate(); } + + MOCK_METHOD(void, log, (absl::string_view)); + MOCK_METHOD(void, logWithStableName, + (absl::string_view, absl::string_view, absl::string_view, absl::string_view)); + MOCK_METHOD(void, flush, ()); +}; + +TEST(NamedLogtest, OverrideSink) { + NamedLogSink global_sink(Envoy::Logger::Registry::getSink()); + testing::InSequence s; + + { + TlsLogSink tls_sink(Envoy::Logger::Registry::getSink()); + + // Calls on the current thread goes to the TLS sink. + EXPECT_CALL(tls_sink, log(_)); + ENVOY_LOG_MISC(info, "hello tls"); + + // Calls on other threads should use the global sink. + std::thread([&]() { + EXPECT_CALL(global_sink, log(_)); + ENVOY_LOG_MISC(info, "hello global"); + }).join(); + + // Sanity checking that we're still using the TLS sink. + EXPECT_CALL(tls_sink, log(_)); + ENVOY_LOG_MISC(info, "hello tls"); + + // All the logging functions should be delegated to the TLS override. + EXPECT_CALL(tls_sink, flush()); + Registry::getSink()->flush(); + + EXPECT_CALL(tls_sink, logWithStableName(_, _, _, _)); + Registry::getSink()->logWithStableName("foo", "level", "bar", "msg"); + } + + // Now that the TLS sink is out of scope, log calls on this thread should use the global sink + // again. + EXPECT_CALL(global_sink, log(_)); + ENVOY_LOG_MISC(info, "hello global 2"); +} } // namespace Logger } // namespace Envoy