From eac4bba3ea27aa8ad0f55550008f6fbd96834e66 Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Tue, 26 Oct 2021 19:32:31 +0000 Subject: [PATCH 1/8] common: add support for thread local sink overrides This adds support for specifying a SinkDelegate that should be active only on the current thread. This allows for per thread overrides of the logging context, which opens up for overriding the logger for the duration of a dispatcher event as well as overriding the logger for specific function calls. Signed-off-by: Snow Pettersen --- source/common/common/fancy_logger.cc | 9 +++--- source/common/common/logger.cc | 32 +++++++++++++++++---- source/common/common/logger.h | 43 +++++++++++++++++++++++----- test/common/common/logger_test.cc | 37 ++++++++++++++++++++++++ 4 files changed, 104 insertions(+), 17 deletions(-) diff --git a/source/common/common/fancy_logger.cc b/source/common/common/fancy_logger.cc index 4c5686ec9a274..3b45ae7602bf0 100644 --- a/source/common/common/fancy_logger.cc +++ b/source/common/common/fancy_logger.cc @@ -100,12 +100,11 @@ FancyLogLevelMap FancyContext::getAllFancyLogLevelsForTest() ABSL_LOCKS_EXCLUDED } void FancyContext::initSink() { - spdlog::sink_ptr sink = Logger::Registry::getSink(); - Logger::DelegatingLogSinkSharedPtr sp = std::static_pointer_cast(sink); - if (!sp->hasLock()) { + Logger::DelegatingLogSinkSharedPtr sink = Logger::Registry::getSink(); + if (!sink->hasLock()) { static FancyBasicLockable tlock; - sp->setLock(tlock); - sp->setShouldEscape(false); + sink->setLock(tlock); + sink->setShouldEscape(false); } } diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index bc4859fe8ee1b..d9ea41f1c624a 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -31,6 +31,12 @@ SinkDelegate::~SinkDelegate() { assert(previous_delegate_ == nullptr); } +void SinkDelegate::setTlsDelegate() { + assert(previous_delegate_ == nullptr); + previous_delegate_ = log_sink_->tlsDelegate(); + log_sink_->setTlsDelegate(this); +} + void SinkDelegate::setDelegate() { // There should be no previous delegate before this call. assert(previous_delegate_ == nullptr); @@ -38,6 +44,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_delegate_); + previous_delegate_ = nullptr; +} + void SinkDelegate::restoreDelegate() { // Ensures stacked allocation of delegates. assert(log_sink_->delegate() == this); @@ -80,6 +93,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 +113,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) { diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 73425c4c827a5..11b7dfc7d35d7 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -2,6 +2,7 @@ #include #include +#include #include #include #include @@ -115,15 +116,23 @@ 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_; } @@ -165,12 +174,22 @@ 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 { + auto* tls_sink = tlsDelegate(); + if (tls_sink != nullptr) { + tls_sink->flush(); + return; + } absl::ReaderMutexLock lock(&sink_mutex_); sink_->flush(); } @@ -221,6 +240,16 @@ class DelegatingLogSink : public spdlog::sinks::sink { return sink_; } + void setTlsDelegate(SinkDelegate* sink) { *tlsSink() = sink; } + + SinkDelegate* tlsDelegate() { return *tlsSink(); } + + SinkDelegate** tlsSink() { + static thread_local SinkDelegate* tls_sink = nullptr; + + return &tls_sink; + } + SinkDelegate* sink_ ABSL_GUARDED_BY(sink_mutex_){nullptr}; absl::Mutex sink_mutex_; std::unique_ptr stderr_sink_; // Builtin sink to use as a last resort. diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index ba0578abaecf4..2798514eb3026 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -185,5 +185,42 @@ 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)); + void flush() override {} +}; + +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"); + } + + // 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 From a7fc4598871a60e6c2a7291720362d055beb18ae Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Tue, 26 Oct 2021 19:59:20 +0000 Subject: [PATCH 2/8] formatt Signed-off-by: Snow Pettersen --- source/common/common/logger.h | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 11b7dfc7d35d7..5e775fa2600a0 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -226,6 +226,16 @@ class DelegatingLogSink : public spdlog::sinks::sink { */ static std::string escapeLogLine(absl::string_view source); +protected: + // This is virtual in order to allow for multiple DelegatingLogSinks to exist and use different + // thread local overrides. A base class defining a new thread_local would be necessary for each + // DelegatingLogSink that will coexist. + virtual SinkDelegate** tlsSink() { + static thread_local SinkDelegate* tls_sink = nullptr; + + return &tls_sink; + } + private: friend class SinkDelegate; @@ -244,12 +254,6 @@ class DelegatingLogSink : public spdlog::sinks::sink { SinkDelegate* tlsDelegate() { return *tlsSink(); } - SinkDelegate** tlsSink() { - static thread_local SinkDelegate* tls_sink = nullptr; - - return &tls_sink; - } - SinkDelegate* sink_ ABSL_GUARDED_BY(sink_mutex_){nullptr}; absl::Mutex sink_mutex_; std::unique_ptr stderr_sink_; // Builtin sink to use as a last resort. From c806fe424720cff827fb8ae620f5111a03adfe4e Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Tue, 26 Oct 2021 20:00:32 +0000 Subject: [PATCH 3/8] revert fancy Signed-off-by: Snow Pettersen --- source/common/common/fancy_logger.cc | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/source/common/common/fancy_logger.cc b/source/common/common/fancy_logger.cc index 3b45ae7602bf0..4c5686ec9a274 100644 --- a/source/common/common/fancy_logger.cc +++ b/source/common/common/fancy_logger.cc @@ -100,11 +100,12 @@ FancyLogLevelMap FancyContext::getAllFancyLogLevelsForTest() ABSL_LOCKS_EXCLUDED } void FancyContext::initSink() { - Logger::DelegatingLogSinkSharedPtr sink = Logger::Registry::getSink(); - if (!sink->hasLock()) { + spdlog::sink_ptr sink = Logger::Registry::getSink(); + Logger::DelegatingLogSinkSharedPtr sp = std::static_pointer_cast(sink); + if (!sp->hasLock()) { static FancyBasicLockable tlock; - sink->setLock(tlock); - sink->setShouldEscape(false); + sp->setLock(tlock); + sp->setShouldEscape(false); } } From 6ca11e111098b1def83eae710974ef0b70f46621 Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Wed, 27 Oct 2021 15:35:38 +0000 Subject: [PATCH 4/8] remove iostream Signed-off-by: Snow Pettersen --- source/common/common/logger.h | 1 - 1 file changed, 1 deletion(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 5e775fa2600a0..a7fc623c0f387 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -2,7 +2,6 @@ #include #include -#include #include #include #include From 53f0394dee211fa858f2cdfce2157bda08f02634 Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Thu, 28 Oct 2021 01:30:47 +0000 Subject: [PATCH 5/8] pr feedback Signed-off-by: Snow Pettersen --- source/common/common/logger.cc | 11 ++++++----- source/common/common/logger.h | 17 +++++++---------- 2 files changed, 13 insertions(+), 15 deletions(-) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index d9ea41f1c624a..ca33887e5d319 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -27,13 +27,14 @@ 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_delegate_ == nullptr); - previous_delegate_ = log_sink_->tlsDelegate(); + assert(previous_tls_delegate_ == nullptr); + previous_tls_delegate_ = log_sink_->tlsDelegate(); log_sink_->setTlsDelegate(this); } @@ -47,8 +48,8 @@ void SinkDelegate::setDelegate() { void SinkDelegate::restoreTlsDelegate() { // Ensures stacked allocation of delegates. assert(log_sink_->tlsDelegate() == this); - log_sink_->setTlsDelegate(previous_delegate_); - previous_delegate_ = nullptr; + log_sink_->setTlsDelegate(previous_tls_delegate_); + previous_tls_delegate_ = nullptr; } void SinkDelegate::restoreDelegate() { diff --git a/source/common/common/logger.h b/source/common/common/logger.h index a7fc623c0f387..920d1412e7b18 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -138,6 +138,7 @@ class SinkDelegate : NonCopyable { private: SinkDelegate* previous_delegate_{nullptr}; + SinkDelegate* previous_tls_delegate_{nullptr} DelegatingLogSinkSharedPtr log_sink_; }; @@ -225,16 +226,6 @@ class DelegatingLogSink : public spdlog::sinks::sink { */ static std::string escapeLogLine(absl::string_view source); -protected: - // This is virtual in order to allow for multiple DelegatingLogSinks to exist and use different - // thread local overrides. A base class defining a new thread_local would be necessary for each - // DelegatingLogSink that will coexist. - virtual SinkDelegate** tlsSink() { - static thread_local SinkDelegate* tls_sink = nullptr; - - return &tls_sink; - } - private: friend class SinkDelegate; @@ -249,6 +240,12 @@ class DelegatingLogSink : public spdlog::sinks::sink { return sink_; } + SinkDelegate** tlsSink() { + static thread_local SinkDelegate* tls_sink = nullptr; + + return &tls_sink; + } + void setTlsDelegate(SinkDelegate* sink) { *tlsSink() = sink; } SinkDelegate* tlsDelegate() { return *tlsSink(); } From 3ed1f56485ba56282b02eb2eeeba46af0aa857ed Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Thu, 28 Oct 2021 01:31:55 +0000 Subject: [PATCH 6/8] format Signed-off-by: Snow Pettersen --- source/common/common/logger.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 920d1412e7b18..76a9ebeb6d38e 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -138,7 +138,7 @@ class SinkDelegate : NonCopyable { private: SinkDelegate* previous_delegate_{nullptr}; - SinkDelegate* previous_tls_delegate_{nullptr} + SinkDelegate* previous_tls_delegate_{nullptr}; DelegatingLogSinkSharedPtr log_sink_; }; From 7b511f6cabe9ba6cffd5a911ee467ea13e59d073 Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Thu, 28 Oct 2021 15:21:08 +0000 Subject: [PATCH 7/8] improve coverage Signed-off-by: Snow Pettersen --- test/common/common/logger_test.cc | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index 2798514eb3026..d1ecf385ba95a 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -192,7 +192,7 @@ struct TlsLogSink : SinkDelegate { 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 {} + MOCK_METHOD(void, flush, ()); }; TEST(NamedLogtest, OverrideSink) { @@ -215,6 +215,13 @@ TEST(NamedLogtest, OverrideSink) { // 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 From a9e012de65bd5e4854098d383492a2f10df2e37f Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Fri, 29 Oct 2021 21:39:10 +0000 Subject: [PATCH 8/8] move to cc file Signed-off-by: Snow Pettersen --- source/common/common/logger.cc | 20 ++++++++++++++++++++ source/common/common/logger.h | 23 ++++------------------- 2 files changed, 24 insertions(+), 19 deletions(-) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index ca33887e5d319..ec0e4a99a5c63 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -134,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 76a9ebeb6d38e..2dd45c7e8daaa 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -184,15 +184,7 @@ class DelegatingLogSink : public spdlog::sinks::sink { } // spdlog::sinks::sink void log(const spdlog::details::log_msg& msg) override; - void flush() override { - auto* tls_sink = tlsDelegate(); - if (tls_sink != nullptr) { - tls_sink->flush(); - return; - } - 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)); } @@ -239,16 +231,9 @@ class DelegatingLogSink : public spdlog::sinks::sink { absl::ReaderMutexLock lock(&sink_mutex_); return sink_; } - - SinkDelegate** tlsSink() { - static thread_local SinkDelegate* tls_sink = nullptr; - - return &tls_sink; - } - - void setTlsDelegate(SinkDelegate* sink) { *tlsSink() = sink; } - - SinkDelegate* tlsDelegate() { return *tlsSink(); } + SinkDelegate** tlsSink(); + void setTlsDelegate(SinkDelegate* sink); + SinkDelegate* tlsDelegate(); SinkDelegate* sink_ ABSL_GUARDED_BY(sink_mutex_){nullptr}; absl::Mutex sink_mutex_;