From 2a2a658cc3fb33f761ea9760ed8a30cfc5e0404e Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Mon, 2 Apr 2018 18:26:28 -0400 Subject: [PATCH] server: Create a mocking infrastructure for logging, by delegating the log-sinks (#2930) This is a fork of #2912, including only the logs mocking, and new tests for existing logging behavior in admin. Risk Level: Low Testing: //test/... Docs Changes: N/A Release Notes: N/A Signed-off-by: Joshua Marantz --- STYLE.md | 6 ++ source/common/common/logger.cc | 90 +++++++++++++------- source/common/common/logger.h | 145 ++++++++++++++++++++++++--------- source/server/http/admin.cc | 8 +- source/server/server.cc | 5 +- source/server/server.h | 1 + test/mocks/BUILD | 5 +- test/mocks/common.h | 2 + test/server/http/BUILD | 1 + test/server/http/admin_test.cc | 25 ++++-- test/test_common/BUILD | 18 ++++ test/test_common/logging.cc | 35 ++++++++ test/test_common/logging.h | 90 ++++++++++++++++++++ 13 files changed, 352 insertions(+), 79 deletions(-) create mode 100644 test/test_common/logging.cc create mode 100644 test/test_common/logging.h diff --git a/STYLE.md b/STYLE.md index 1ec465f983e7..6a1ff4eab003 100644 --- a/STYLE.md +++ b/STYLE.md @@ -109,6 +109,12 @@ A few general notes on our error handling philosophy: that there is complete test coverage for the degraded case.** Additionally, the user should be aware of the degraded state minimally via an error log of level warn or greater and via the increment of a stat. +* If you do need to log a non-fatal warning or error, you can unit-test it with EXPECT_LOG_CONTAINS + or EXPECT_NO_LOGS from [logging.h](test/test_common/logging.h). It's generally bad practice to + test by depending on log messages unless the actual behavior being validated is logging. + It's preferable to export statistics to enable consumption by external monitoring for any + behavior that should be externally consumed or to introduce appropriate internal interfaces + such as mocks for internal behavior. * The error handling philosophy described herein is based on the assumption that Envoy is deployed using industry best practices (primarily canary). Major and obvious errors should always be caught in canary. If a low rate error leads to periodic crash cycling when deployed to diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index e82e4535a7cc..23310ceb6bcc 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -1,5 +1,6 @@ #include "common/common/logger.h" +#include // use direct system-assert to avoid cyclic dependency. #include #include #include @@ -25,48 +26,81 @@ Logger::Logger(const std::string& name) { logger_->flush_on(spdlog::level::critical); } -void LockingStderrOrFileSink::logToStdErr() { log_file_.reset(); } +SinkDelegate::SinkDelegate(DelegatingLogSinkPtr log_sink) + : previous_delegate_(log_sink->delegate()), log_sink_(log_sink) { + log_sink->setDelegate(this); +} -void LockingStderrOrFileSink::logToFile(const std::string& log_path, - AccessLog::AccessLogManager& log_manager) { - log_file_ = log_manager.createAccessLog(log_path); +SinkDelegate::~SinkDelegate() { + assert(log_sink_->delegate() == this); // Ensures stacked allocation of delegates. + log_sink_->setDelegate(previous_delegate_); } -std::vector& Registry::allLoggers() { - static std::vector* all_loggers = - new std::vector({ALL_LOGGER_IDS(GENERATE_LOGGER)}); - return *all_loggers; +FileSinkDelegate::FileSinkDelegate(const std::string& log_path, + AccessLog::AccessLogManager& log_manager, + DelegatingLogSinkPtr log_sink) + : SinkDelegate(log_sink), log_file_(log_manager.createAccessLog(log_path)) {} + +void FileSinkDelegate::log(absl::string_view msg) { + // Logfiles have internal locking to ensure serial, non-interleaved + // writes, so no additional locking needed here. + log_file_->write(msg); } -void LockingStderrOrFileSink::log(const spdlog::details::log_msg& msg) { - if (log_file_) { - // Logfiles have internal locking to ensure serial, non-interleaved - // writes, so no additional locking needed here. - log_file_->write(msg.formatted.str()); - } else { - Thread::OptionalLockGuard guard(lock_); - std::cerr << msg.formatted.str(); - } +void FileSinkDelegate::flush() { + // Logfiles have internal locking to ensure serial, non-interleaved + // writes, so no additional locking needed here. + log_file_->flush(); } -void LockingStderrOrFileSink::flush() { - if (log_file_) { - // Logfiles have internal locking to ensure serial, non-interleaved - // writes, so no additional locking needed here. - log_file_->flush(); - } else { - Thread::OptionalLockGuard guard(lock_); - std::cerr << std::flush; - } +StderrSinkDelegate::StderrSinkDelegate(DelegatingLogSinkPtr log_sink) : SinkDelegate(log_sink) {} + +void StderrSinkDelegate::log(absl::string_view msg) { + Thread::OptionalLockGuard guard(lock_); + std::cerr << msg; } -spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast(id)].logger_; } +void StderrSinkDelegate::flush() { + Thread::OptionalLockGuard guard(lock_); + std::cerr << std::flush; +} + +void DelegatingLogSink::log(const spdlog::details::log_msg& msg) { + sink_->log(msg.formatted.str()); +} + +DelegatingLogSinkPtr DelegatingLogSink::init() { + DelegatingLogSinkPtr delegating_sink(new DelegatingLogSink); + delegating_sink->stderr_sink_ = std::make_unique(delegating_sink); + return delegating_sink; +} -void Registry::initialize(uint64_t log_level, const std::string& log_format, +void Registry::initialize(spdlog::level::level_enum log_level, const std::string& log_format, Thread::BasicLockable& lock) { + // TODO(jmarantz): I think it would be more robust to push a separate lockable + // SinkDelegate onto the stack for the lifetime of the lock, so we don't crash + // if we try to log anything after the context owning the lock is destroyed. getSink()->setLock(lock); + setLogLevel(log_level); + setLogFormat(log_format); +} + +std::vector& Registry::allLoggers() { + static std::vector* all_loggers = + new std::vector({ALL_LOGGER_IDS(GENERATE_LOGGER)}); + return *all_loggers; +} + +spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast(id)].logger_; } + +void Registry::setLogLevel(spdlog::level::level_enum log_level) { for (Logger& logger : allLoggers()) { logger.logger_->set_level(static_cast(log_level)); + } +} + +void Registry::setLogFormat(const std::string& log_format) { + for (Logger& logger : allLoggers()) { logger.logger_->set_pattern(log_format); } } diff --git a/source/common/common/logger.h b/source/common/common/logger.h index d4759d55b0be..9d1b0b366168 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -12,6 +12,7 @@ #include "common/common/fmt.h" #include "common/common/macros.h" +#include "absl/strings/string_view.h" #include "spdlog/spdlog.h" namespace Envoy { @@ -53,10 +54,6 @@ enum class Id { */ class Logger { public: - std::string levelString() const { return spdlog::level::level_names[logger_->level()]; } - std::string name() const { return logger_->name(); } - void setLevel(spdlog::level::level_enum level) const { logger_->set_level(level); } - /* This is simple mapping between Logger severity levels and spdlog severity levels. * The only reason for this mapping is to go around the fact that spdlog defines level as err * but the method to log at err level is called LOGGER.error not LOGGER.err. All other level are @@ -72,6 +69,11 @@ class Logger { off = spdlog::level::off } levels; + std::string levelString() const { return spdlog::level::level_names[logger_->level()]; } + std::string name() const { return logger_->name(); } + void setLevel(spdlog::level::level_enum level) { logger_->set_level(level); } + spdlog::level::level_enum level() const { return logger_->level(); } + static const char* DEFAULT_LOG_FORMAT; private: @@ -82,46 +84,99 @@ class Logger { friend class Registry; }; +class DelegatingLogSink; +typedef std::shared_ptr DelegatingLogSinkPtr; + /** - * An optionally locking stderr or file logging sink. - * - * This sink outputs to either stderr or to a file. It shares both implementations (instead of - * being two separate classes) because we can't setup file logging until after the AccessLogManager - * is available, but by that time some loggers have cached their logger from the registry already, - * so we need to be able switch implementations without replacing the object. + * Captures a logging sink that can be delegated to for a bounded amount of time. + * On destruction, logging is reverted to its previous state. SinkDelegates must + * be allocated/freed as a stack. */ -class LockingStderrOrFileSink : public spdlog::sinks::sink { +class SinkDelegate { public: + explicit SinkDelegate(DelegatingLogSinkPtr log_sink); + virtual ~SinkDelegate(); + + virtual void log(absl::string_view msg) PURE; + virtual void flush() PURE; + +protected: + SinkDelegate* previous_delegate() { return previous_delegate_; } + +private: + SinkDelegate* previous_delegate_; + DelegatingLogSinkPtr log_sink_; +}; + +/** + * SinkDelegate that writes log messages to a file. + */ +class FileSinkDelegate : public SinkDelegate { +public: + FileSinkDelegate(const std::string& log_path, AccessLog::AccessLogManager& log_manager, + DelegatingLogSinkPtr log_sink); + + // SinkDelegate + void log(absl::string_view msg) override; + void flush() override; + +private: + Filesystem::FileSharedPtr log_file_; +}; + +/** + * SinkDelegate that writes log messages to stderr. + */ +class StderrSinkDelegate : public SinkDelegate { +public: + explicit StderrSinkDelegate(DelegatingLogSinkPtr log_sink); + + // SinkDelegate + void log(absl::string_view msg) override; + void flush() override; + + bool hasLock() const { return lock_ != nullptr; } void setLock(Thread::BasicLockable& lock) { lock_ = &lock; } - /** - * Configure this object to log to stderr. - * - * @note This method is not thread-safe and can only be called when no other threads - * are logging. - */ - void logToStdErr(); +private: + Thread::BasicLockable* lock_{}; +}; - /** - * Configure this object to log to a file. - * - * @note This method is not thread-safe and can only be called when no other threads - * are logging. - */ - void logToFile(const std::string& log_path, AccessLog::AccessLogManager& log_manager); +/** + * Stacks logging sinks, so you can temporarily override the logging mechanism, restoring + * the prevoius state when the DelegatingSink is destructed. + */ +class DelegatingLogSink : public spdlog::sinks::sink { +public: + void setLock(Thread::BasicLockable& lock) { stderr_sink_->setLock(lock); } // spdlog::sinks::sink void log(const spdlog::details::log_msg& msg) override; - void flush() override; + void flush() override { sink_->flush(); } /** * @return bool whether a lock has been established. */ - bool hasLock() const { return lock_ != nullptr; } + bool hasLock() const { return stderr_sink_->hasLock(); } + + // Constructs a new DelegatingLogSink, sets up the default sink to stderr, + // and returns a shared_ptr to it. A shared_ptr is required for sinks used + // in spdlog::logger; it would not otherwise be required in Envoy. This method + // must own the construction process because StderrSinkDelegate needs access to + // the DelegatingLogSinkPtr, not just the DelegatingLogSink*, and that is only + // available after construction. + static DelegatingLogSinkPtr init(); private: - Thread::BasicLockable* lock_{}; - Filesystem::FileSharedPtr log_file_; + friend class SinkDelegate; + + DelegatingLogSink() = default; + + void setDelegate(SinkDelegate* sink) { sink_ = sink; } + SinkDelegate* delegate() { return sink_; } + + SinkDelegate* sink_{nullptr}; + std::unique_ptr stderr_sink_; // Builtin sink to use as a last resort. }; /** @@ -139,21 +194,35 @@ class Registry { /** * @return the singleton sink to use for all loggers. */ - static std::shared_ptr getSink() { - static std::shared_ptr sink(new LockingStderrOrFileSink()); + static DelegatingLogSinkPtr getSink() { + static DelegatingLogSinkPtr sink = DelegatingLogSink::init(); return sink; } - /** - * Initialize the logging system from server options. + /* + * Initialize the logging system with the specified lock and log level. + * This is equivalalent to setLogLevel, setLogFormat, and setLock, which + * can be called individually as well, e.g. to set the log level without + * changing the lock or format. */ - static void initialize(uint64_t log_level, const std::string& log_format, + static void initialize(spdlog::level::level_enum log_level, const std::string& log_format, Thread::BasicLockable& lock); /** - * @return const std::vector& the installed loggers. + * Sets the minimum log severity required to print messages. + * Messages below this loglevel will be suppressed. + */ + static void setLogLevel(spdlog::level::level_enum log_level); + + /** + * Sets the log format. + */ + static void setLogFormat(const std::string& log_format); + + /** + * @return std::vector& the installed loggers. */ - static const std::vector& loggers() { return allLoggers(); } + static std::vector& loggers() { return allLoggers(); } /** * @Return bool whether the registry has been initialized. @@ -198,7 +267,9 @@ template class Loggable { #define ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL) \ (static_cast(Envoy::Logger::Logger::LEVEL) >= LOGGER.level()) -// Compare levels before invoking logger +// Compare levels before invoking logger. This is an optimization to avoid +// executing expressions computing log contents when they would be suppressed. +// The same filtering will also occur in spdlog::logger. #define ENVOY_LOG_COMP_AND_LOG(LOGGER, LEVEL, ...) \ do { \ if (ENVOY_LOG_COMP_LEVEL(LOGGER, LEVEL)) { \ diff --git a/source/server/http/admin.cc b/source/server/http/admin.cc index 6d70eee40ab8..b44c3235a8d2 100644 --- a/source/server/http/admin.cc +++ b/source/server/http/admin.cc @@ -173,13 +173,13 @@ bool AdminImpl::changeLogLevel(const Http::Utility::QueryParams& params) { // Now either change all levels or a single level. if (name == "level") { ENVOY_LOG(debug, "change all log levels: level='{}'", level); - for (const Logger::Logger& logger : Logger::Registry::loggers()) { + for (Logger::Logger& logger : Logger::Registry::loggers()) { logger.setLevel(static_cast(level_to_use)); } } else { ENVOY_LOG(debug, "change log level: name='{}' level='{}'", name, level); - const Logger::Logger* logger_to_change = nullptr; - for (const Logger::Logger& logger : Logger::Registry::loggers()) { + Logger::Logger* logger_to_change = nullptr; + for (Logger::Logger& logger : Logger::Registry::loggers()) { if (logger.name() == name) { logger_to_change = &logger; break; @@ -846,7 +846,7 @@ bool AdminImpl::addHandler(const std::string& prefix, const std::string& help_te // make no sense as part of a URL path: ? and :. const std::string::size_type pos = prefix.find_first_of("&\"'<>?:"); if (pos != std::string::npos) { - ENVOY_LOG(error, "filter \"{}\" contains invalid character '{}'", prefix[pos]); + ENVOY_LOG(error, "filter \"{}\" contains invalid character '{}'", prefix, prefix[pos]); return false; } diff --git a/source/server/server.cc b/source/server/server.cc index 3cc6a2a8a22e..ac69ba79a483 100644 --- a/source/server/server.cc +++ b/source/server/server.cc @@ -56,7 +56,8 @@ InstanceImpl::InstanceImpl(Options& options, Network::Address::InstanceConstShar try { if (!options.logPath().empty()) { try { - Logger::Registry::getSink()->logToFile(options.logPath(), access_log_manager_); + file_logger_ = std::make_unique( + options.logPath(), access_log_manager_, Logger::Registry::getSink()); } catch (const EnvoyException& e) { throw EnvoyException( fmt::format("Failed to open log-file '{}'. e.what(): {}", options.logPath(), e.what())); @@ -80,7 +81,7 @@ InstanceImpl::~InstanceImpl() { // Stop logging to file before all the AccessLogManager and its dependencies are // destructed to avoid crashing at shutdown. - Logger::Registry::getSink()->logToStdErr(); + file_logger_.reset(); } Upstream::ClusterManager& InstanceImpl::clusterManager() { return config_->clusterManager(); } diff --git a/source/server/server.h b/source/server/server.h index eaa7de4d16cd..645f0a006746 100644 --- a/source/server/server.h +++ b/source/server/server.h @@ -205,6 +205,7 @@ class InstanceImpl : Logger::Loggable, public Instance { InitManagerImpl init_manager_; std::unique_ptr guard_dog_; bool terminated_; + std::unique_ptr file_logger_; }; } // Server diff --git a/test/mocks/BUILD b/test/mocks/BUILD index aafea79471e1..4b51d6b0d729 100644 --- a/test/mocks/BUILD +++ b/test/mocks/BUILD @@ -12,5 +12,8 @@ envoy_cc_test_library( name = "common_lib", srcs = ["common.cc"], hdrs = ["common.h"], - deps = ["//include/envoy/common:time_interface"], + deps = [ + "//include/envoy/common:time_interface", + "//source/common/common:logger_lib", + ], ) diff --git a/test/mocks/common.h b/test/mocks/common.h index c222f44b8988..24280683117a 100644 --- a/test/mocks/common.h +++ b/test/mocks/common.h @@ -2,6 +2,8 @@ #include "envoy/common/time.h" +#include "common/common/logger.h" + #include "absl/strings/string_view.h" #include "gmock/gmock.h" diff --git a/test/server/http/BUILD b/test/server/http/BUILD index 36cd09ea97e1..18400f2b3c22 100644 --- a/test/server/http/BUILD +++ b/test/server/http/BUILD @@ -21,6 +21,7 @@ envoy_cc_test( "//test/mocks/runtime:runtime_mocks", "//test/mocks/server:server_mocks", "//test/test_common:environment_lib", + "//test/test_common:logging_lib", "//test/test_common:network_utility_lib", "//test/test_common:utility_lib", ], diff --git a/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index 09b11bdf4b12..9a17bf7af7c8 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -14,6 +14,7 @@ #include "test/mocks/runtime/mocks.h" #include "test/mocks/server/mocks.h" #include "test/test_common/environment.h" +#include "test/test_common/logging.h" #include "test/test_common/network_utility.h" #include "test/test_common/printers.h" #include "test/test_common/utility.h" @@ -80,6 +81,7 @@ class AdminInstanceTest : public testing::TestWithParam admin_bad_address_out_path; + EXPECT_LOG_CONTAINS( + "critical", "cannot open admin address output file " + bad_path + " for writing.", + admin_bad_address_out_path = + std::make_unique("/dev/null", cpu_profile_path_, bad_path, + Network::Test::getCanonicalLoopbackAddress(GetParam()), + server_, listener_scope_.createScope("listener.admin."))); EXPECT_FALSE(std::ifstream(bad_path)); } @@ -143,7 +149,7 @@ TEST_P(AdminInstanceTest, CustomHandler) { }; // Test removable handler. - EXPECT_TRUE(admin_.addHandler("/foo/bar", "hello", callback, true, false)); + EXPECT_NO_LOGS(EXPECT_TRUE(admin_.addHandler("/foo/bar", "hello", callback, true, false))); Http::HeaderMapImpl header_map; Buffer::OwnedImpl response; EXPECT_EQ(Http::Code::Accepted, admin_.runCallback("/foo/bar", header_map, response)); @@ -169,15 +175,20 @@ TEST_P(AdminInstanceTest, RejectHandlerWithXss) { auto callback = [](absl::string_view, Http::HeaderMap&, Buffer::Instance&) -> Http::Code { return Http::Code::Accepted; }; - EXPECT_FALSE( - admin_.addHandler("/foo", "hello", callback, true, false)); + EXPECT_LOG_CONTAINS("error", + "filter \"/foo\" contains invalid character '<'", + EXPECT_FALSE(admin_.addHandler("/foo", "hello", + callback, true, false))); } TEST_P(AdminInstanceTest, RejectHandlerWithEmbeddedQuery) { auto callback = [](absl::string_view, Http::HeaderMap&, Buffer::Instance&) -> Http::Code { return Http::Code::Accepted; }; - EXPECT_FALSE(admin_.addHandler("/bar?queryShouldNotBeInPrefix", "hello", callback, true, false)); + EXPECT_LOG_CONTAINS("error", + "filter \"/bar?queryShouldNotBeInPrefix\" contains invalid character '?'", + EXPECT_FALSE(admin_.addHandler("/bar?queryShouldNotBeInPrefix", "hello", + callback, true, false))); } TEST_P(AdminInstanceTest, EscapeHelpTextWithPunctuation) { diff --git a/test/test_common/BUILD b/test/test_common/BUILD index a3778514378c..1ee420eacf3d 100644 --- a/test/test_common/BUILD +++ b/test/test_common/BUILD @@ -87,6 +87,24 @@ envoy_cc_test_library( ], ) +envoy_cc_test_library( + name = "logging_lib", + srcs = ["logging.cc"], + hdrs = ["logging.h"], + deps = [ + "//source/common/common:assert_lib", + "//source/common/common:logger_lib", + ], +) + +envoy_cc_test_library( + name = "lua_wrappers_lib", + hdrs = ["lua_wrappers.h"], + deps = [ + "//test/mocks/thread_local:thread_local_mocks", + ], +) + envoy_cc_library( name = "threadsafe_singleton_injector_lib", hdrs = ["threadsafe_singleton_injector.h"], diff --git a/test/test_common/logging.cc b/test/test_common/logging.cc new file mode 100644 index 000000000000..d53a175f3c52 --- /dev/null +++ b/test/test_common/logging.cc @@ -0,0 +1,35 @@ +#include "test/test_common/logging.h" + +#include "common/common/assert.h" + +namespace Envoy { + +LogLevelSetter::LogLevelSetter(spdlog::level::level_enum log_level) { + for (Logger::Logger& logger : Logger::Registry::loggers()) { + previous_levels_.push_back(logger.level()); + logger.setLevel(log_level); + } +} + +LogLevelSetter::~LogLevelSetter() { + auto prev_level = previous_levels_.begin(); + for (Logger::Logger& logger : Logger::Registry::loggers()) { + ASSERT(prev_level != previous_levels_.end()); + logger.setLevel(*prev_level); + ++prev_level; + } + ASSERT(prev_level == previous_levels_.end()); +} + +LogRecordingSink::LogRecordingSink(Logger::DelegatingLogSinkPtr log_sink) + : Logger::SinkDelegate(log_sink) {} +LogRecordingSink::~LogRecordingSink() {} + +void LogRecordingSink::log(absl::string_view msg) { + previous_delegate()->log(msg); + messages_.push_back(std::string(msg)); +} + +void LogRecordingSink::flush() { previous_delegate()->flush(); } + +} // namespace Envoy diff --git a/test/test_common/logging.h b/test/test_common/logging.h new file mode 100644 index 000000000000..c3930b0d2c09 --- /dev/null +++ b/test/test_common/logging.h @@ -0,0 +1,90 @@ +#pragma once + +#include +#include +#include + +#include "common/common/logger.h" + +#include "absl/strings/str_join.h" +#include "absl/strings/str_split.h" +#include "spdlog/spdlog.h" + +namespace Envoy { + +/** + * Provides a mechanism to temporarily set the logging level on + * construction, restoring its previous state on dstruction. + * + * The log_level is the minimum log severity required to print messages. + * Messages below this loglevel will be suppressed. + * + * Note that during the scope of this object, command-line overrides, eg + * --log-level trace, will not take effect. + * + * Also note: instantiating this setter should only occur when the system is + * in a quiescent state, e.g. at startup or between tests. + * + * This is intended for use in EXPECT_LOG_CONTAINS and similar macros. + */ +class LogLevelSetter { +public: + explicit LogLevelSetter(spdlog::level::level_enum log_level); + ~LogLevelSetter(); + +private: + std::vector previous_levels_; +}; + +/** + * Records log messages in a vector, forwarding them to the previous + * delegate. This is useful for unit-testing log messages while still being able + * to see them on stderr. + * + * Also note: instantiating this sink should only occur when the system is + * in a quiescent state, e.g. at startup or between tests + * + * This is intended for use in EXPECT_LOG_CONTAINS and similar macros. + */ +class LogRecordingSink : public Logger::SinkDelegate { +public: + explicit LogRecordingSink(Logger::DelegatingLogSinkPtr log_sink); + virtual ~LogRecordingSink(); + + // Logger::SinkDelgate + void log(absl::string_view msg) override; + void flush() override; + + const std::vector& messages() const { return messages_; } + +private: + std::vector messages_; +}; + +// Validates that when stmt is executed, exactly one log message containing substr will be emitted. +#define EXPECT_LOG_CONTAINS(loglevel, substr, stmt) \ + do { \ + LogLevelSetter save_levels(spdlog::level::trace); \ + LogRecordingSink log_recorder(Logger::Registry::getSink()); \ + stmt; \ + ASSERT_EQ(1, log_recorder.messages().size()); \ + std::string recorded_log = log_recorder.messages()[0]; \ + std::vector pieces = absl::StrSplit(recorded_log, "]["); \ + /* Parse "[2018-04-02 19:06:08.629][15][warn][admin] source/file.cc:691] message ..." */ \ + ASSERT_LE(3, pieces.size()); \ + EXPECT_EQ(loglevel, std::string(pieces[2])); /* error message is legible if cast to string */ \ + EXPECT_TRUE(absl::string_view(recorded_log).find(substr) != absl::string_view::npos) \ + << "\n Actual Log: " << recorded_log << "\n Expected Substring: " << substr; \ + } while (false) + +// Validates that when stmt is executed, no logs will be emitted. +#define EXPECT_NO_LOGS(stmt) \ + do { \ + LogLevelSetter save_levels(spdlog::level::trace); \ + LogRecordingSink log_recorder(Logger::Registry::getSink()); \ + stmt; \ + const std::vector logs = log_recorder.messages(); \ + ASSERT_EQ(0, logs.size()) << " Logs:\n " << absl::StrJoin(logs, "\n "); \ + } while (false) + +} // namespace Envoy