From f9dc58187774d5c7d7845046609220a79e30d1e5 Mon Sep 17 00:00:00 2001 From: Joshua Marantz Date: Mon, 2 Apr 2018 15:20:17 -0400 Subject: [PATCH] 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)