From 984bebd5e9efb57221b488a945dcf1dc7146cf5b Mon Sep 17 00:00:00 2001 From: Snow Pettersen Date: Mon, 1 Nov 2021 21:11:55 +0000 Subject: [PATCH] logging: include spdlog log_msg in log to SinkDelegate This allows sinks to inspect the log line details without parsing the formatted message. Signed-off-by: Snow Pettersen --- source/common/common/logger.cc | 8 ++-- source/common/common/logger.h | 21 ++++++++++- source/common/common/logger_delegates.cc | 2 +- source/common/common/logger_delegates.h | 2 +- test/common/common/logger_test.cc | 47 +++++++++++++++++------- test/test_common/logging.cc | 4 +- test/test_common/logging.h | 2 +- 7 files changed, 61 insertions(+), 25 deletions(-) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index ec0e4a99a5c63..a418cc046e02b 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -66,7 +66,7 @@ StderrSinkDelegate::StderrSinkDelegate(DelegatingLogSinkSharedPtr log_sink) StderrSinkDelegate::~StderrSinkDelegate() { restoreDelegate(); } -void StderrSinkDelegate::log(absl::string_view msg) { +void StderrSinkDelegate::log(absl::string_view msg, const spdlog::details::log_msg&) { Thread::OptionalLockGuard guard(lock_); std::cerr << msg; } @@ -94,11 +94,11 @@ void DelegatingLogSink::log(const spdlog::details::log_msg& msg) { } lock.Release(); - auto log_to_sink = [this, msg_view](SinkDelegate& sink) { + auto log_to_sink = [this, msg_view, msg](SinkDelegate& sink) { if (should_escape_) { - sink.log(escapeLogLine(msg_view)); + sink.log(escapeLogLine(msg_view), msg); } else { - sink.log(msg_view); + sink.log(msg_view, msg); } }; auto* tls_sink = tlsDelegate(); diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 2dd45c7e8daaa..0d55c68fa5573 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -109,9 +109,26 @@ class SinkDelegate : NonCopyable { explicit SinkDelegate(DelegatingLogSinkSharedPtr log_sink); virtual ~SinkDelegate(); - virtual void log(absl::string_view msg) PURE; + /** + * Called to log a single log line. + * @param formatted_msg The final, formatted message. + * @param the original log message, including additional metadata. + */ + virtual void log(absl::string_view msg, const spdlog::details::log_msg& log_msg) PURE; + + /** + * Called to log a single log line with a stable name. + * @param stable_name stable name of this log line. + * @param level the string representation of the log level for this log line. + * @param component the component this log was logged via. + * @param msg the log line to log. + */ virtual void logWithStableName(absl::string_view stable_name, absl::string_view level, absl::string_view component, absl::string_view msg); + + /** + * Called to flush the log sink. + */ virtual void flush() PURE; protected: @@ -151,7 +168,7 @@ class StderrSinkDelegate : public SinkDelegate { ~StderrSinkDelegate() override; // SinkDelegate - void log(absl::string_view msg) override; + void log(absl::string_view msg, const spdlog::details::log_msg& log_msg) override; void flush() override; bool hasLock() const { return lock_ != nullptr; } diff --git a/source/common/common/logger_delegates.cc b/source/common/common/logger_delegates.cc index 8f008b296fb7e..46371a5de2e1e 100644 --- a/source/common/common/logger_delegates.cc +++ b/source/common/common/logger_delegates.cc @@ -19,7 +19,7 @@ FileSinkDelegate::FileSinkDelegate(const std::string& log_path, FileSinkDelegate::~FileSinkDelegate() { restoreDelegate(); } -void FileSinkDelegate::log(absl::string_view msg) { +void FileSinkDelegate::log(absl::string_view msg, const spdlog::details::log_msg&) { // Log files have internal locking to ensure serial, non-interleaved // writes, so no additional locking needed here. log_file_->write(msg); diff --git a/source/common/common/logger_delegates.h b/source/common/common/logger_delegates.h index f9e1d7da69cc1..c85d0b1b46a0f 100644 --- a/source/common/common/logger_delegates.h +++ b/source/common/common/logger_delegates.h @@ -24,7 +24,7 @@ class FileSinkDelegate : public SinkDelegate { ~FileSinkDelegate() override; // SinkDelegate - void log(absl::string_view msg) override; + void log(absl::string_view msg, const spdlog::details::log_msg& log_msg) override; void flush() override; private: diff --git a/test/common/common/logger_test.cc b/test/common/common/logger_test.cc index d1ecf385ba95a..faeb939f2d211 100644 --- a/test/common/common/logger_test.cc +++ b/test/common/common/logger_test.cc @@ -10,6 +10,7 @@ #include "gtest/gtest.h" using testing::_; +using testing::HasSubstr; using testing::Invoke; namespace Envoy { @@ -154,11 +155,11 @@ 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(); } +struct MockLogSink : SinkDelegate { + MockLogSink(DelegatingLogSinkSharedPtr log_sink) : SinkDelegate(log_sink) { setDelegate(); } + ~MockLogSink() override { restoreDelegate(); } - MOCK_METHOD(void, log, (absl::string_view)); + MOCK_METHOD(void, log, (absl::string_view, const spdlog::details::log_msg&)); MOCK_METHOD(void, logWithStableName, (absl::string_view, absl::string_view, absl::string_view, absl::string_view)); void flush() override {} @@ -167,7 +168,7 @@ struct NamedLogSink : SinkDelegate { class NamedLogTest : public Loggable, public testing::Test {}; TEST_F(NamedLogTest, NamedLogsAreSentToSink) { - NamedLogSink sink(Envoy::Logger::Registry::getSink()); + MockLogSink sink(Envoy::Logger::Registry::getSink()); Envoy::Logger::Registry::setLogLevel(spdlog::level::info); // Log level is above debug, so we shouldn't get any logs. @@ -175,12 +176,14 @@ TEST_F(NamedLogTest, NamedLogsAreSentToSink) { Envoy::Logger::Registry::setLogLevel(spdlog::level::debug); - EXPECT_CALL(sink, log(_)); + EXPECT_CALL(sink, log(_, _)); EXPECT_CALL(sink, logWithStableName("test_event", "debug", "assert", "test log 1")); ENVOY_LOG_EVENT(debug, "test_event", "test {} {}", "log", 1); // Verify that ENVOY_LOG_EVENT_TO_LOGGER does the right thing. - EXPECT_CALL(sink, log(_)).WillOnce(Invoke([](auto log) { EXPECT_TRUE(log.find("[misc]")); })); + EXPECT_CALL(sink, log(_, _)).WillOnce(Invoke([](auto log, const auto&) { + EXPECT_TRUE(log.find("[misc]")); + })); EXPECT_CALL(sink, logWithStableName("misc_event", "debug", "misc", "log")); ENVOY_LOG_EVENT_TO_LOGGER(Registry::getLog(Id::misc), debug, "misc_event", "log"); } @@ -189,31 +192,32 @@ struct TlsLogSink : SinkDelegate { TlsLogSink(DelegatingLogSinkSharedPtr log_sink) : SinkDelegate(log_sink) { setTlsDelegate(); } ~TlsLogSink() override { restoreTlsDelegate(); } - MOCK_METHOD(void, log, (absl::string_view)); + MOCK_METHOD(void, log, (absl::string_view, const spdlog::details::log_msg&)); 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()); +// Verifies that we can register a thread local sink override. +TEST(TlsLoggingOverrideTest, OverrideSink) { + MockLogSink 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(_)); + 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(_)); + 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(_)); + EXPECT_CALL(tls_sink, log(_, _)); ENVOY_LOG_MISC(info, "hello tls"); // All the logging functions should be delegated to the TLS override. @@ -226,8 +230,23 @@ TEST(NamedLogtest, OverrideSink) { // 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(_)); + EXPECT_CALL(global_sink, log(_, _)); ENVOY_LOG_MISC(info, "hello global 2"); } + +TEST(LoggerTest, LogWithLogDetails) { + Envoy::Logger::Registry::setLogLevel(spdlog::level::info); + + MockLogSink sink(Envoy::Logger::Registry::getSink()); + + EXPECT_CALL(sink, log(_, _)).WillOnce(Invoke([](auto msg, auto& log) { + EXPECT_THAT(msg, HasSubstr("[info]")); + EXPECT_THAT(msg, HasSubstr("hello")); + + EXPECT_EQ(log.logger_name, "misc"); + })); + ENVOY_LOG_MISC(info, "hello"); +} + } // namespace Logger } // namespace Envoy diff --git a/test/test_common/logging.cc b/test/test_common/logging.cc index 3663feb0c83dd..ecfe04dbf9cf1 100644 --- a/test/test_common/logging.cc +++ b/test/test_common/logging.cc @@ -41,8 +41,8 @@ LogRecordingSink::LogRecordingSink(Logger::DelegatingLogSinkSharedPtr log_sink) LogRecordingSink::~LogRecordingSink() { restoreDelegate(); } -void LogRecordingSink::log(absl::string_view msg) { - previousDelegate()->log(msg); +void LogRecordingSink::log(absl::string_view msg, const spdlog::details::log_msg& log_msg) { + previousDelegate()->log(msg, log_msg); absl::MutexLock ml(&mtx_); messages_.push_back(std::string(msg)); diff --git a/test/test_common/logging.h b/test/test_common/logging.h index 2d6252b2c68ec..09cb5cdb5fa35 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -54,7 +54,7 @@ class LogRecordingSink : public Logger::SinkDelegate { ~LogRecordingSink() override; // Logger::SinkDelegate - void log(absl::string_view msg) override; + void log(absl::string_view msg, const spdlog::details::log_msg& log_msg) override; void flush() override; const std::vector messages() const {