EXPECT_LOG_CONTAINS compares loglevel as well as the overall substrin…

…g check.

Signed-off-by: Joshua Marantz <[email protected]>

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

test/server/http/admin_test.cc

@@ -79,8 +79,7 @@ class AdminInstanceTest : public testing::TestWithParam<Network::Address::IpVers
         cpu_profile_path_(TestEnvironment::temporaryPath("envoy.prof")),
         admin_("/dev/null", cpu_profile_path_, address_out_path_,
                Network::Test::getCanonicalLoopbackAddress(GetParam()), server_,
-               listener_scope_.createScope("listener.admin.")),
-        expect_no_logs_(true) {
+               listener_scope_.createScope("listener.admin.")) {
 
     EXPECT_EQ(std::chrono::milliseconds(100), admin_.drainTimeout());
     admin_.tracingStats().random_sampling_.inc();
@@ -92,7 +91,6 @@ class AdminInstanceTest : public testing::TestWithParam<Network::Address::IpVers
   NiceMock<MockInstance> 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<AdminImpl> 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<AdminImpl>(
-                          "/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<AdminImpl>("/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<script>alert('hi')</script>\" contains invalid character '<'",
+  EXPECT_LOG_CONTAINS("error",
+                      "filter \"/foo<script>alert('hi')</script>\" contains invalid character '<'",
                       EXPECT_FALSE(admin_.addHandler("/foo<script>alert('hi')</script>", "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)));
 }

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<absl::string_view> 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)