From 62d724ae734c8bfba3d63ab1221e2abfa963b8f5 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Wed, 28 Mar 2018 22:32:02 -0400 Subject: [PATCH 01/12] Create a mocking infrastructure for logging, by delegating the log-sinks. Add testing in admin_test.cc that no logs get emitted, most of the time, except for one test where an unwriteable output filename is named. Signed-off-by: Joshua Marantz --- STYLE.md | 2 + source/common/common/logger.cc | 88 ++++++++++++++++-------- source/common/common/logger.h | 122 +++++++++++++++++++++++++-------- source/server/server.cc | 5 +- source/server/server.h | 1 + test/mocks/BUILD | 5 +- test/mocks/common.h | 21 ++++++ test/server/http/admin_test.cc | 37 +++++++++- 8 files changed, 221 insertions(+), 60 deletions(-) diff --git a/STYLE.md b/STYLE.md index 1ec465f983e7..21786497276b 100644 --- a/STYLE.md +++ b/STYLE.md @@ -109,6 +109,8 @@ 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 by instantiating a + MockLogSink from test/mocks/common.h. * 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..adcf4a572ddd 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, 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(uint64_t 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..6f1571a167b8 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 { @@ -82,46 +83,96 @@ 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; + +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,17 +190,30 @@ 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, Thread::BasicLockable& lock); + /** + * Sets the log level. + */ + static void setLogLevel(uint64_t log_level); + + /** + * Sets the log format. + */ + static void setLogFormat(const std::string& log_format); + /** * @return const std::vector& the installed loggers. */ diff --git a/source/server/server.cc b/source/server/server.cc index 90c58c9ec4be..2a624b1132f4 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..028c2fb0159c 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" @@ -46,6 +48,25 @@ class MockMonotonicTimeSource : public MonotonicTimeSource { MOCK_METHOD0(currentTime, MonotonicTime()); }; +// This Mock logging sink is not implemented using the gmock infrastructure, due to +// apparent limitations in the g++ type system, which fails to compile +// EXPECT_CALL(mock_logger_, log(HasSubstr("substr"))) due to difficulty between +// std::string and absl::string_view. clang compiles it fine. +class MockLogSink : public Logger::SinkDelegate { +public: + MockLogSink() : Logger::SinkDelegate(Logger::Registry::getSink()) {} + virtual ~MockLogSink(){}; + + // Logger::SinkDelgate + void log(absl::string_view msg) override { messages_.push_back(std::string(msg)); } + void flush() override {} + + const std::vector& messages() const { return messages_; } + +private: + std::vector messages_; +}; + // Captures absl::string_view parameters into temp strings, for use // with gmock's SaveArg. Providing an absl::string_view compiles, // but fails because by the time you examine the saved value, its diff --git a/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index bc8f543eb783..2937284de857 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -11,6 +11,7 @@ #include "server/http/admin.h" +#include "test/mocks/common.h" #include "test/mocks/runtime/mocks.h" #include "test/mocks/server/mocks.h" #include "test/test_common/environment.h" @@ -21,6 +22,7 @@ #include "gmock/gmock.h" #include "gtest/gtest.h" +using testing::HasSubstr; using testing::NiceMock; using testing::_; @@ -39,8 +41,13 @@ class AdminFilterTest : public testing::TestWithParam server_; Stats::IsolatedStoreImpl listener_scope_; + MockLogSink mock_logger_; AdminImpl admin_; AdminFilter filter_; NiceMock callbacks_; @@ -77,17 +84,43 @@ class AdminInstanceTest : public testing::TestWithParam logs = mock_logger_.messages(); + if (!logs.empty()) { + return logs[0]; + } + return ""; + } + + bool log0Contains(absl::string_view substr) { + expect_no_logs_ = false; + EXPECT_EQ(1, mock_logger_.messages().size()); + absl::string_view log_0 = log0(); + return log_0.find(substr) != absl::string_view::npos; } std::string address_out_path_; std::string cpu_profile_path_; NiceMock server_; Stats::IsolatedStoreImpl listener_scope_; + MockLogSink mock_logger_; AdminImpl admin_; + bool expect_no_logs_; }; INSTANTIATE_TEST_CASE_P(IpVersions, AdminInstanceTest, @@ -132,6 +165,8 @@ TEST_P(AdminInstanceTest, AdminBadAddressOutPath) { Network::Test::getCanonicalLoopbackAddress(GetParam()), server_, listener_scope_.createScope("listener.admin.")); EXPECT_FALSE(std::ifstream(bad_path)); + EXPECT_TRUE(log0Contains("cannot open admin address output file " + bad_path + + " for writing.")) << log0(); } TEST_P(AdminInstanceTest, CustomHandler) { From b4f417fbfb7ae9173285bf81de04870752b9f763 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Wed, 28 Mar 2018 23:19:50 -0400 Subject: [PATCH 02/12] Re-arrange the temps so we don't drop the string while holding a reference to it. Signed-off-by: Joshua Marantz --- test/server/http/admin_test.cc | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index 2937284de857..6512947d6d0c 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -41,9 +41,7 @@ class AdminFilterTest : public testing::TestWithParam server_; Stats::IsolatedStoreImpl listener_scope_; @@ -93,7 +91,7 @@ class AdminInstanceTest : public testing::TestWithParam Date: Thu, 29 Mar 2018 16:38:53 -0400 Subject: [PATCH 03/12] Rename MockLogSink to LogRecordingSink, and have it chain so logs can be seen. Signed-off-by: Joshua Marantz --- source/common/common/logger.cc | 4 ++-- source/common/common/logger.h | 18 +++++++++++------- source/server/http/admin.cc | 8 ++++---- test/mocks/common.h | 19 ------------------- test/server/http/BUILD | 1 + test/server/http/admin_test.cc | 18 ++++++++++++++---- test/test_common/BUILD | 10 ++++++++++ 7 files changed, 42 insertions(+), 36 deletions(-) diff --git a/source/common/common/logger.cc b/source/common/common/logger.cc index adcf4a572ddd..23310ceb6bcc 100644 --- a/source/common/common/logger.cc +++ b/source/common/common/logger.cc @@ -75,7 +75,7 @@ DelegatingLogSinkPtr DelegatingLogSink::init() { 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 @@ -93,7 +93,7 @@ std::vector& Registry::allLoggers() { spdlog::logger& Registry::getLog(Id id) { return *allLoggers()[static_cast(id)].logger_; } -void Registry::setLogLevel(uint64_t log_level) { +void Registry::setLogLevel(spdlog::level::level_enum log_level) { for (Logger& logger : allLoggers()) { logger.logger_->set_level(static_cast(log_level)); } diff --git a/source/common/common/logger.h b/source/common/common/logger.h index 6f1571a167b8..ba7b0de361c8 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -54,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 @@ -73,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: @@ -99,6 +100,9 @@ class 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_; @@ -201,13 +205,13 @@ class Registry { * 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); /** * Sets the log level. */ - static void setLogLevel(uint64_t log_level); + static void setLogLevel(spdlog::level::level_enum log_level); /** * Sets the log format. @@ -217,7 +221,7 @@ class Registry { /** * @return const 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. diff --git a/source/server/http/admin.cc b/source/server/http/admin.cc index b71a0d9a62f8..99aa57159ed7 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; @@ -809,7 +809,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/test/mocks/common.h b/test/mocks/common.h index 028c2fb0159c..24280683117a 100644 --- a/test/mocks/common.h +++ b/test/mocks/common.h @@ -48,25 +48,6 @@ class MockMonotonicTimeSource : public MonotonicTimeSource { MOCK_METHOD0(currentTime, MonotonicTime()); }; -// This Mock logging sink is not implemented using the gmock infrastructure, due to -// apparent limitations in the g++ type system, which fails to compile -// EXPECT_CALL(mock_logger_, log(HasSubstr("substr"))) due to difficulty between -// std::string and absl::string_view. clang compiles it fine. -class MockLogSink : public Logger::SinkDelegate { -public: - MockLogSink() : Logger::SinkDelegate(Logger::Registry::getSink()) {} - virtual ~MockLogSink(){}; - - // Logger::SinkDelgate - void log(absl::string_view msg) override { messages_.push_back(std::string(msg)); } - void flush() override {} - - const std::vector& messages() const { return messages_; } - -private: - std::vector messages_; -}; - // Captures absl::string_view parameters into temp strings, for use // with gmock's SaveArg. Providing an absl::string_view compiles, // but fails because by the time you examine the saved value, its 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 6512947d6d0c..a8c14fb8fc02 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -15,6 +15,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" @@ -33,7 +34,8 @@ class AdminFilterTest : public testing::TestWithParam server_; Stats::IsolatedStoreImpl listener_scope_; - MockLogSink mock_logger_; + LogLevelSetter log_level_setter_; + LogRecordingSink mock_logger_; AdminImpl admin_; AdminFilter filter_; NiceMock callbacks_; @@ -80,6 +83,7 @@ class AdminInstanceTest : public testing::TestWithParam server_; Stats::IsolatedStoreImpl listener_scope_; - MockLogSink mock_logger_; + LogLevelSetter log_level_setter_; + LogRecordingSink mock_logger_; AdminImpl admin_; bool expect_no_logs_; }; @@ -200,6 +204,9 @@ TEST_P(AdminInstanceTest, RejectHandlerWithXss) { }; EXPECT_FALSE( admin_.addHandler("/foo", "hello", callback, true, false)); + EXPECT_TRUE(log0Contains("filter \"/foo\" contains invalid " + "character '<'")) + << log0(); } TEST_P(AdminInstanceTest, RejectHandlerWithEmbeddedQuery) { @@ -207,6 +214,9 @@ TEST_P(AdminInstanceTest, RejectHandlerWithEmbeddedQuery) { return Http::Code::Accepted; }; EXPECT_FALSE(admin_.addHandler("/bar?queryShouldNotBeInPrefix", "hello", callback, true, false)); + EXPECT_TRUE(log0Contains("filter \"/bar?queryShouldNotBeInPrefix\" contains invalid " + "character '?'")) + << log0(); } TEST_P(AdminInstanceTest, EscapeHelpTextWithPunctuation) { diff --git a/test/test_common/BUILD b/test/test_common/BUILD index 67bf3b5307c5..067e6fcc2122 100644 --- a/test/test_common/BUILD +++ b/test/test_common/BUILD @@ -88,6 +88,16 @@ 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"], From 0382c7ed8ad585e16cd4aa7773845ac3d74df1e4 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Thu, 29 Mar 2018 16:40:06 -0400 Subject: [PATCH 04/12] Add RAII log-level set/restore, so we don't affect the rest of the binary when tweaking flags. Signed-off-by: Joshua Marantz --- test/test_common/logging.cc | 34 +++++++++++++++++++++++++++ test/test_common/logging.h | 46 +++++++++++++++++++++++++++++++++++++ 2 files changed, 80 insertions(+) create mode 100644 test/test_common/logging.cc create mode 100644 test/test_common/logging.h diff --git a/test/test_common/logging.cc b/test/test_common/logging.cc new file mode 100644 index 000000000000..413f39b1f71e --- /dev/null +++ b/test/test_common/logging.cc @@ -0,0 +1,34 @@ +#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::SinkDelegate(Logger::Registry::getSink()) {} +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..8886ef25dd59 --- /dev/null +++ b/test/test_common/logging.h @@ -0,0 +1,46 @@ +#pragma once + +#include +#include +#include + +#include "common/common/logger.h" + +#include "spdlog/spdlog.h" + +namespace Envoy { + +/** + * Provides a mechanism to temporarily set the logging level on + * construction, restoring its previous state on dstruction. + */ +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. + */ +class LogRecordingSink : public Logger::SinkDelegate { +public: + LogRecordingSink(); + 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_; +}; + +} // namespace Envoy From 9b944c9ef2ad11ee968eb679afe82ce4a86f7d4e Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Thu, 29 Mar 2018 19:36:07 -0400 Subject: [PATCH 05/12] remove extraneous includes. Signed-off-by: Joshua Marantz --- test/server/http/admin_test.cc | 2 -- 1 file changed, 2 deletions(-) diff --git a/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index a8c14fb8fc02..fbe17cb47732 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -11,7 +11,6 @@ #include "server/http/admin.h" -#include "test/mocks/common.h" #include "test/mocks/runtime/mocks.h" #include "test/mocks/server/mocks.h" #include "test/test_common/environment.h" @@ -23,7 +22,6 @@ #include "gmock/gmock.h" #include "gtest/gtest.h" -using testing::HasSubstr; using testing::NiceMock; using testing::_; From e6dfa6b0828ed71e7d09824a76aa71b12a137d4c Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Thu, 29 Mar 2018 19:41:21 -0400 Subject: [PATCH 06/12] Add commentary explaining loglevel semantics. Signed-off-by: Joshua Marantz --- source/common/common/logger.h | 3 ++- test/server/http/admin_test.cc | 23 ++++++++++++----------- test/test_common/logging.h | 3 +++ 3 files changed, 17 insertions(+), 12 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index ba7b0de361c8..bfe1600c5bef 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -209,7 +209,8 @@ class Registry { Thread::BasicLockable& lock); /** - * Sets the log level. + * 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); diff --git a/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index fbe17cb47732..d2a9f435816c 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -98,7 +98,7 @@ class AdminInstanceTest : public testing::TestWithParam logs = mock_logger_.messages(); if (!logs.empty()) { return logs[0]; @@ -106,10 +106,10 @@ class AdminInstanceTest : public testing::TestWithParamalert('hi')", "hello", callback, true, false)); - EXPECT_TRUE(log0Contains("filter \"/foo\" contains invalid " - "character '<'")) - << log0(); + EXPECT_TRUE(recordedLogContains("filter \"/foo\" contains invalid " + "character '<'")) + << recordedLog(); } TEST_P(AdminInstanceTest, RejectHandlerWithEmbeddedQuery) { @@ -212,9 +213,9 @@ TEST_P(AdminInstanceTest, RejectHandlerWithEmbeddedQuery) { return Http::Code::Accepted; }; EXPECT_FALSE(admin_.addHandler("/bar?queryShouldNotBeInPrefix", "hello", callback, true, false)); - EXPECT_TRUE(log0Contains("filter \"/bar?queryShouldNotBeInPrefix\" contains invalid " - "character '?'")) - << log0(); + EXPECT_TRUE(recordedLogContains("filter \"/bar?queryShouldNotBeInPrefix\" contains invalid " + "character '?'")) + << recordedLog(); } TEST_P(AdminInstanceTest, EscapeHelpTextWithPunctuation) { diff --git a/test/test_common/logging.h b/test/test_common/logging.h index 8886ef25dd59..f67030f5f925 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -13,6 +13,9 @@ 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. */ class LogLevelSetter { public: From 3b512d9b472e2e7d8e4eb76b1532a208d9dcf000 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Fri, 30 Mar 2018 09:22:17 -0400 Subject: [PATCH 07/12] Add testing macros to bound the scope of logging mocks and level overrides. Signed-off-by: Joshua Marantz --- source/common/common/logger.h | 6 ++-- test/server/http/admin_test.cc | 59 ++++++++-------------------------- test/test_common/logging.cc | 3 +- test/test_common/logging.h | 36 ++++++++++++++++++++- 4 files changed, 55 insertions(+), 49 deletions(-) diff --git a/source/common/common/logger.h b/source/common/common/logger.h index bfe1600c5bef..9d1b0b366168 100644 --- a/source/common/common/logger.h +++ b/source/common/common/logger.h @@ -220,7 +220,7 @@ class Registry { static void setLogFormat(const std::string& log_format); /** - * @return const std::vector& the installed loggers. + * @return std::vector& the installed loggers. */ static std::vector& loggers() { return allLoggers(); } @@ -267,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/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index d2a9f435816c..e75870ac053d 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -32,8 +32,7 @@ class AdminFilterTest : public testing::TestWithParam server_; Stats::IsolatedStoreImpl listener_scope_; - LogLevelSetter log_level_setter_; - LogRecordingSink mock_logger_; AdminImpl admin_; AdminFilter filter_; NiceMock callbacks_; @@ -81,7 +76,6 @@ class AdminInstanceTest : public testing::TestWithParam logs = mock_logger_.messages(); - if (!logs.empty()) { - return logs[0]; - } - return ""; - } - - bool recordedLogContains(absl::string_view substr) { - expect_no_logs_ = false; - EXPECT_EQ(1, mock_logger_.messages().size()); - return absl::string_view(recordedLog()).find(substr) != absl::string_view::npos; - } - std::string address_out_path_; std::string cpu_profile_path_; NiceMock server_; Stats::IsolatedStoreImpl listener_scope_; - LogLevelSetter log_level_setter_; - LogRecordingSink mock_logger_; AdminImpl admin_; bool expect_no_logs_; }; @@ -160,13 +132,13 @@ TEST_P(AdminInstanceTest, WriteAddressToFile) { TEST_P(AdminInstanceTest, AdminBadAddressOutPath) { std::string bad_path = TestEnvironment::temporaryPath("some/unlikely/bad/path/admin.address"); - AdminImpl admin_bad_address_out_path("/dev/null", cpu_profile_path_, bad_path, - Network::Test::getCanonicalLoopbackAddress(GetParam()), - server_, listener_scope_.createScope("listener.admin.")); + std::unique_ptr admin_bad_address_out_path; + EXPECT_LOG_CONTAINS("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)); - EXPECT_TRUE( - recordedLogContains("cannot open admin address output file " + bad_path + " for writing.")) - << recordedLog(); } TEST_P(AdminInstanceTest, CustomHandler) { @@ -175,7 +147,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)); @@ -201,21 +173,18 @@ 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_TRUE(recordedLogContains("filter \"/foo\" contains invalid " - "character '<'")) - << recordedLog(); + EXPECT_LOG_CONTAINS("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_TRUE(recordedLogContains("filter \"/bar?queryShouldNotBeInPrefix\" contains invalid " - "character '?'")) - << recordedLog(); + EXPECT_LOG_CONTAINS("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/logging.cc b/test/test_common/logging.cc index 413f39b1f71e..d53a175f3c52 100644 --- a/test/test_common/logging.cc +++ b/test/test_common/logging.cc @@ -21,7 +21,8 @@ LogLevelSetter::~LogLevelSetter() { ASSERT(prev_level == previous_levels_.end()); } -LogRecordingSink::LogRecordingSink() : Logger::SinkDelegate(Logger::Registry::getSink()) {} +LogRecordingSink::LogRecordingSink(Logger::DelegatingLogSinkPtr log_sink) + : Logger::SinkDelegate(log_sink) {} LogRecordingSink::~LogRecordingSink() {} void LogRecordingSink::log(absl::string_view msg) { diff --git a/test/test_common/logging.h b/test/test_common/logging.h index f67030f5f925..1e465b1b6d21 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -16,6 +16,14 @@ namespace Envoy { * * 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: @@ -30,10 +38,15 @@ class LogLevelSetter { * 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: - LogRecordingSink(); + explicit LogRecordingSink(Logger::DelegatingLogSinkPtr log_sink); virtual ~LogRecordingSink(); // Logger::SinkDelgate @@ -46,4 +59,25 @@ class LogRecordingSink : public Logger::SinkDelegate { std::vector messages_; }; +// Validates that when stmt is executed, exactly one log message containing substr will be emitted. +#define EXPECT_LOG_CONTAINS(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]; \ + 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, exactly logs will be emitted. +#define EXPECT_NO_LOGS(stmt) \ + do { \ + LogLevelSetter save_levels(spdlog::level::trace); \ + LogRecordingSink log_recorder(Logger::Registry::getSink()); \ + stmt; \ + ASSERT_EQ(0, log_recorder.messages().size()) << "msg[0]: " << log_recorder.messages()[0]; \ + } while (false) + } // namespace Envoy From 300f65fbb79683c6cc28f07cc9c153cb2b5ac69e Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Fri, 30 Mar 2018 09:29:09 -0400 Subject: [PATCH 08/12] Update style note and add commentary from htuch about preferring stats/mocks to verify functionality. Signed-off-by: Joshua Marantz --- STYLE.md | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/STYLE.md b/STYLE.md index 21786497276b..7bdbd7c7b973 100644 --- a/STYLE.md +++ b/STYLE.md @@ -109,8 +109,11 @@ 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 by instantiating a - MockLogSink from test/mocks/common.h. +* 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 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 From 6d6d39a3e4979a39a96a0c86f5e9b06dc3cebdc3 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Fri, 30 Mar 2018 09:32:49 -0400 Subject: [PATCH 09/12] fix comment typo. Signed-off-by: Joshua Marantz --- test/test_common/logging.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/test_common/logging.h b/test/test_common/logging.h index 1e465b1b6d21..e542c51ae0e8 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -71,7 +71,7 @@ class LogRecordingSink : public Logger::SinkDelegate { << "\n Actual Log: " << recorded_log << "\n Expected Substring: " << substr; \ } while (false) -// Validates that when stmt is executed, exactly logs will be emitted. +// Validates that when stmt is executed, no logs will be emitted. #define EXPECT_NO_LOGS(stmt) \ do { \ LogLevelSetter save_levels(spdlog::level::trace); \ From 7de2f1f3e5f8562b030f5ef26492abf083926261 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Fri, 30 Mar 2018 09:38:52 -0400 Subject: [PATCH 10/12] Show all the logs on an EXPECT_NO_LOGS failure, not just the first one. Signed-off-by: Joshua Marantz --- test/test_common/logging.h | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/test/test_common/logging.h b/test/test_common/logging.h index e542c51ae0e8..97403e187cb3 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -6,6 +6,7 @@ #include "common/common/logger.h" +#include "absl/strings/str_join.h" #include "spdlog/spdlog.h" namespace Envoy { @@ -77,7 +78,8 @@ class LogRecordingSink : public Logger::SinkDelegate { LogLevelSetter save_levels(spdlog::level::trace); \ LogRecordingSink log_recorder(Logger::Registry::getSink()); \ stmt; \ - ASSERT_EQ(0, log_recorder.messages().size()) << "msg[0]: " << log_recorder.messages()[0]; \ + const std::vector logs = log_recorder.messages(); \ + ASSERT_EQ(0, logs.size()) << " Logs:\n " << absl::StrJoin(logs, "\n "); \ } while (false) } // namespace Envoy From f9dc58187774d5c7d7845046609220a79e30d1e5 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Mon, 2 Apr 2018 15:20:17 -0400 Subject: [PATCH 11/12] EXPECT_LOG_CONTAINS compares loglevel as well as the overall substring check. Signed-off-by: Joshua Marantz --- STYLE.md | 11 ++++++----- test/server/http/admin_test.cc | 21 +++++++++++---------- test/test_common/logging.h | 6 +++++- 3 files changed, 22 insertions(+), 16 deletions(-) diff --git a/STYLE.md b/STYLE.md index 7bdbd7c7b973..6a1ff4eab003 100644 --- a/STYLE.md +++ b/STYLE.md @@ -109,11 +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 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. +* 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/test/server/http/admin_test.cc b/test/server/http/admin_test.cc index b718a2150b5d..863be1c8b521 100644 --- a/test/server/http/admin_test.cc +++ b/test/server/http/admin_test.cc @@ -79,8 +79,7 @@ class AdminInstanceTest : public testing::TestWithParam server_; Stats::IsolatedStoreImpl listener_scope_; AdminImpl admin_; - bool expect_no_logs_; }; INSTANTIATE_TEST_CASE_P(IpVersions, AdminInstanceTest, @@ -135,11 +133,12 @@ TEST_P(AdminInstanceTest, WriteAddressToFile) { TEST_P(AdminInstanceTest, AdminBadAddressOutPath) { std::string bad_path = TestEnvironment::temporaryPath("some/unlikely/bad/path/admin.address"); std::unique_ptr admin_bad_address_out_path; - EXPECT_LOG_CONTAINS("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_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)); } @@ -175,7 +174,8 @@ TEST_P(AdminInstanceTest, RejectHandlerWithXss) { auto callback = [](absl::string_view, Http::HeaderMap&, Buffer::Instance&) -> Http::Code { return Http::Code::Accepted; }; - EXPECT_LOG_CONTAINS("filter \"/foo\" contains invalid character '<'", + EXPECT_LOG_CONTAINS("error", + "filter \"/foo\" contains invalid character '<'", EXPECT_FALSE(admin_.addHandler("/foo", "hello", callback, true, false))); } @@ -184,7 +184,8 @@ TEST_P(AdminInstanceTest, RejectHandlerWithEmbeddedQuery) { auto callback = [](absl::string_view, Http::HeaderMap&, Buffer::Instance&) -> Http::Code { return Http::Code::Accepted; }; - EXPECT_LOG_CONTAINS("filter \"/bar?queryShouldNotBeInPrefix\" contains invalid character '?'", + EXPECT_LOG_CONTAINS("error", + "filter \"/bar?queryShouldNotBeInPrefix\" contains invalid character '?'", EXPECT_FALSE(admin_.addHandler("/bar?queryShouldNotBeInPrefix", "hello", callback, true, false))); } diff --git a/test/test_common/logging.h b/test/test_common/logging.h index 97403e187cb3..d3f9cd42c810 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -7,6 +7,7 @@ #include "common/common/logger.h" #include "absl/strings/str_join.h" +#include "absl/strings/str_split.h" #include "spdlog/spdlog.h" namespace Envoy { @@ -61,13 +62,16 @@ class LogRecordingSink : public Logger::SinkDelegate { }; // Validates that when stmt is executed, exactly one log message containing substr will be emitted. -#define EXPECT_LOG_CONTAINS(substr, stmt) \ +#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, "]["); \ + ASSERT_LE(3, pieces.size()); \ + EXPECT_EQ(loglevel, std::string(pieces[2])); \ EXPECT_TRUE(absl::string_view(recorded_log).find(substr) != absl::string_view::npos) \ << "\n Actual Log: " << recorded_log << "\n Expected Substring: " << substr; \ } while (false) From a0a5cb538df2ea647a14dcf6cfe5a73b29ea0c82 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Mon, 2 Apr 2018 15:30:49 -0400 Subject: [PATCH 12/12] Add comment indicating what's being parsed with the the StrSplit. Signed-off-by: Joshua Marantz --- test/test_common/logging.h | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/test_common/logging.h b/test/test_common/logging.h index d3f9cd42c810..c3930b0d2c09 100644 --- a/test/test_common/logging.h +++ b/test/test_common/logging.h @@ -70,8 +70,9 @@ class LogRecordingSink : public Logger::SinkDelegate { 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])); \ + 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)