/proc/self/cwd/test/test_common/logging.h

Source (jump to first uncovered line)
#pragma once

#include <cstdint>
#include <string>
#include <vector>

#include "source/common/common/assert.h"
#include "source/common/common/logger.h"

#include "absl/strings/str_join.h"
#include "absl/strings/str_split.h"
#include "absl/synchronization/mutex.h"
#include "spdlog/spdlog.h"

namespace Envoy {

/**
 * Provides a mechanism to temporarily set the logging level on
 * construction, restoring its previous state on destruction.
 *
 * 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, e.g.,
 * --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<spdlog::level::level_enum> previous_levels_;
  FineGrainLogLevelMap previous_fine_grain_levels_;
};

/**
 * Records log messages in a vector<string>, 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::DelegatingLogSinkSharedPtr log_sink);
  ~LogRecordingSink() override;

  // Logger::SinkDelegate
  void log(absl::string_view msg, const spdlog::details::log_msg& log_msg) override;
  void flush() override;

  const std::vector<std::string> messages() const {
    absl::MutexLock ml(&mtx_);
    std::vector<std::string> copy(messages_);
    return copy;
  }

private:
  mutable absl::Mutex mtx_;
  std::vector<std::string> messages_ ABSL_GUARDED_BY(mtx_);
};

using StringPair = std::pair<std::string, std::string>;

using ExpectedLogMessages = std::vector<StringPair>;

// Below macros specify Envoy:: before class names so that the macro can be used outside of
// namespace Envoy.

// Alias for EXPECT_LOG_CONTAINS_ALL_OF_HELPER, with escaped=true
#define EXPECT_LOG_CONTAINS_ALL_OF_ESCAPED(expected_messages, stmt)                                \
  EXPECT_LOG_CONTAINS_ALL_OF_HELPER(expected_messages, stmt, true)

// Alias for EXPECT_LOG_CONTAINS_ALL_OF_HELPER, with escaped=false
#define EXPECT_LOG_CONTAINS_ALL_OF(expected_messages, stmt)                                        \
  EXPECT_LOG_CONTAINS_ALL_OF_HELPER(expected_messages, stmt, false)

// Validates that when stmt is executed, log messages containing substr and loglevel will be
// emitted. Escaped=true sets the behavior to function like the --log-format-escaped CLI flag.
// Failure message e.g.,
//
// Logs:
//  [2018-04-12 05:51:00.245][7290192][debug][upstream] grpc_mux_impl.cc:160] Received gRPC
//  [2018-04-12 05:51:00.246][7290192][warning][upstream] grpc_mux_impl.cc:63] Called bar
//  [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:80] Sending foo
//  Does NOT contain:
//    'warning', 'Too many sendDiscoveryRequest calls for baz’
//    'warning', 'Too man sendDiscoveryRequest calls for foo'
#define EXPECT_LOG_CONTAINS_ALL_OF_HELPER(expected_messages, stmt, escaped)                        \
  do {                                                                                             \
    ASSERT_FALSE(expected_messages.empty()) << "Expected messages cannot be empty.";               \
    ::Envoy::Assert::resetEnvoyBugCountersForTest();                                               \
    Envoy::LogLevelSetter save_levels(spdlog::level::trace);                                       \
    Envoy::Logger::DelegatingLogSinkSharedPtr sink_ptr = Envoy::Logger::Registry::getSink();       \
    sink_ptr->setShouldEscape(escaped);                                                            \
    Envoy::LogRecordingSink log_recorder(sink_ptr);                                                \
    stmt;                                                                                          \
    auto messages = log_recorder.messages();                                                       \
    if (messages.empty()) {                                                                        \
      FAIL() << "Expected message(s), but NONE was recorded.";                                     \
    }                                                                                              \
    Envoy::ExpectedLogMessages failed_expectations;                                                \
    for (const Envoy::StringPair& expected : expected_messages) {                                  \
      const auto log_message =                                                                     \
          std::find_if(messages.begin(), messages.end(), [&expected](const std::string& message) { \
            return (message.find(expected.second) != std::string::npos) &&                         \
                   (message.find(expected.first) != std::string::npos);                            \
          });                                                                                      \
      if (log_message == messages.end()) {                                                         \
        failed_expectations.push_back(expected);                                                   \
      }                                                                                            \
    }                                                                                              \
    if (!failed_expectations.empty()) {                                                            \
      std::string failed_message;                                                                  \
      absl::StrAppend(&failed_message, "\nLogs:\n ", absl::StrJoin(messages, " "),                 \
                      "\n Do NOT contain:\n");                                                     \
      for (const auto& expectation : failed_expectations) {                                        \
        absl::StrAppend(&failed_message, "  '", expectation.first, "', '", expectation.second,     \
                        "'\n");                                                                    \
      }                                                                                            \
      FAIL() << failed_message;                                                                    \
    }                                                                                              \
  } while (false)

// Validates that when stmt is executed, log message containing substr and loglevel will NOT be
// emitted. Failure message e.g.,
//
// Logs:
//  [2018-04-12 05:51:00.245][7290192][warning][upstream] grpc_mux_impl.cc:160] Received gRPC
//  [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:63] Called bar
//  Should NOT contain:
//   'warning', 'Received gRPC’
#define EXPECT_LOG_NOT_CONTAINS(loglevel, substr, stmt)                                            \
  do {                                                                                             \
    Envoy::LogLevelSetter save_levels(spdlog::level::trace);                                       \
    Envoy::LogRecordingSink log_recorder(Envoy::Logger::Registry::getSink());                      \
    stmt;                                                                                          \
    auto messages = log_recorder.messages();                                                       \
    for (const std::string& message : messages) {                                                  \
      if ((message.find(substr) != std::string::npos) &&                                           \
          (message.find(loglevel) != std::string::npos)) {                                         \
        FAIL() << "\nLogs:\n " << absl::StrJoin(messages, " ") << "\n Should NOT contain:\n '"     \
               << loglevel << "', '" << substr "'\n";                                              \
      }                                                                                            \
    }                                                                                              \
  } while (false)

// Validates that when stmt is executed, the supplied substring matches at least one log message.
// Failure message e.g.,
//
// Logs:
//  [2018-04-12 05:51:00.245][7290192][debug][upstream] grpc_mux_impl.cc:160] Received gRPC
//  [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:80] Sending foo
//  Do NOT contain:
//    'warning', 'Too many sendDiscoveryRequest calls for baz’
#define EXPECT_LOG_CONTAINS(loglevel, substr, stmt)                                                \
  do {                                                                                             \
    const Envoy::ExpectedLogMessages message{{loglevel, substr}};                                  \
    EXPECT_LOG_CONTAINS_ALL_OF(message, stmt);                                                     \
  } while (false)

// Validates that when stmt is executed, the supplied substring occurs exactly the specified
// number of times.
#define EXPECT_LOG_CONTAINS_N_TIMES(loglevel, substr, expected_occurrences, stmt)                  \
  do {                                                                                             \
    Envoy::LogLevelSetter save_levels(spdlog::level::trace);                                       \
    Envoy::LogRecordingSink log_recorder(Envoy::Logger::Registry::getSink());                      \
    stmt;                                                                                          \
    auto messages = log_recorder.messages();                                                       \
    uint64_t actual_occurrences = 0;                                                               \
    for (const std::string& message : messages) {                                                  \
      if ((message.find(substr) != std::string::npos) &&                                           \
          (message.find(loglevel) != std::string::npos)) {                                         \
        actual_occurrences++;                                                                      \
      }                                                                                            \
    }                                                                                              \
    EXPECT_EQ(expected_occurrences, actual_occurrences);                                           \
  } while (false)

// Validates that when stmt is executed, no logs will be emitted.
// Expected equality of these values:
//   0
//   logs.size()
//     Which is: 3
//  Logs:
//   [2018-04-12 05:51:00.245][7290192][debug][upstream] grpc_mux_impl.cc:160] Received gRPC
//   [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:80] Sending foo
#define EXPECT_NO_LOGS(stmt)                                                                       \
  do {                                                                                             \
    Envoy::LogLevelSetter save_levels(spdlog::level::trace);                                       \
    Envoy::LogRecordingSink log_recorder(Envoy::Logger::Registry::getSink());                      \
    stmt;                                                                                          \
    const std::vector<std::string> logs = log_recorder.messages();                                 \
    ASSERT_EQ(0, logs.size()) << " Logs:\n   " << absl::StrJoin(logs, "   ");                      \
  } while (false)

// Validates that when stmt is executed, the supplied substring is eventually logged.
// This both waits infinitely (not ideal) and walks the full log list every time (not ideal).
#define WAIT_FOR_LOG_CONTAINS(loglevel_raw, substr_raw, stmt)                                      \
  do {                                                                                             \
    Envoy::LogLevelSetter save_levels(spdlog::level::trace);                                       \
    Envoy::Logger::DelegatingLogSinkSharedPtr sink_ptr = Envoy::Logger::Registry::getSink();       \
    std::string loglevel = loglevel_raw;                                                           \
    std::string substr = substr_raw;                                                               \
    Envoy::LogRecordingSink log_recorder(sink_ptr);                                                \
    stmt;                                                                                          \
    while (true) {                                                                                 \
      auto messages = log_recorder.messages();                                                     \
      if (messages.empty()) {                                                                      \
        continue;                                                                                  \
      }                                                                                            \
      const auto log_message = std::find_if(                                                       \
          messages.begin(), messages.end(), [&substr, loglevel](const std::string& message) {      \
            return (message.find(substr) != std::string::npos) &&                                  \
                   (message.find(loglevel) != std::string::npos);                                  \
          });                                                                                      \
      if (log_message != messages.end()) {                                                         \
        break;                                                                                     \
      }                                                                                            \
    }                                                                                              \
  } while (false)

} // namespace Envoy

Coverage Report

Created: 2024-09-19 09:45

Line	Count	Source (jump to first uncovered line)
1		#pragma once
2
3		#include <cstdint>
4		#include <string>
5		#include <vector>
6
7		#include "source/common/common/assert.h"
8		#include "source/common/common/logger.h"
9
10		#include "absl/strings/str_join.h"
11		#include "absl/strings/str_split.h"
12		#include "absl/synchronization/mutex.h"
13		#include "spdlog/spdlog.h"
14
15		namespace Envoy {
16
17		/**
18		* Provides a mechanism to temporarily set the logging level on
19		* construction, restoring its previous state on destruction.
20		*
21		* The log_level is the minimum log severity required to print messages.
22		* Messages below this loglevel will be suppressed.
23		*
24		* Note that during the scope of this object, command-line overrides, e.g.,
25		* --log-level trace, will not take effect.
26		*
27		* Also note: instantiating this setter should only occur when the system is
28		* in a quiescent state, e.g. at startup or between tests.
29		*
30		* This is intended for use in EXPECT_LOG_CONTAINS and similar macros.
31		*/
32		class LogLevelSetter {
33		public:
34		explicit LogLevelSetter(spdlog::level::level_enum log_level);
35		~LogLevelSetter();
36
37		private:
38		std::vector<spdlog::level::level_enum> previous_levels_;
39		FineGrainLogLevelMap previous_fine_grain_levels_;
40		};
41
42		/**
43		* Records log messages in a vector<string>, forwarding them to the previous
44		* delegate. This is useful for unit-testing log messages while still being able
45		* to see them on stderr.
46		*
47		* Also note: instantiating this sink should only occur when the system is
48		* in a quiescent state, e.g. at startup or between tests
49		*
50		* This is intended for use in EXPECT_LOG_CONTAINS and similar macros.
51		*/
52		class LogRecordingSink : public Logger::SinkDelegate {
53		public:
54		explicit LogRecordingSink(Logger::DelegatingLogSinkSharedPtr log_sink);
55		~LogRecordingSink() override;
56
57		// Logger::SinkDelegate
58		void log(absl::string_view msg, const spdlog::details::log_msg& log_msg) override;
59		void flush() override;
60
61	0	const std::vector<std::string> messages() const {
62	0	absl::MutexLock ml(&mtx_);
63	0	std::vector<std::string> copy(messages_);
64	0	return copy;
65	0	}
66
67		private:
68		mutable absl::Mutex mtx_;
69		std::vector<std::string> messages_ ABSL_GUARDED_BY(mtx_);
70		};
71
72		using StringPair = std::pair<std::string, std::string>;
73
74		using ExpectedLogMessages = std::vector<StringPair>;
75
76		// Below macros specify Envoy:: before class names so that the macro can be used outside of
77		// namespace Envoy.
78
79		// Alias for EXPECT_LOG_CONTAINS_ALL_OF_HELPER, with escaped=true
80		#define EXPECT_LOG_CONTAINS_ALL_OF_ESCAPED(expected_messages, stmt) \
81		EXPECT_LOG_CONTAINS_ALL_OF_HELPER(expected_messages, stmt, true)
82
83		// Alias for EXPECT_LOG_CONTAINS_ALL_OF_HELPER, with escaped=false
84		#define EXPECT_LOG_CONTAINS_ALL_OF(expected_messages, stmt) \
85		EXPECT_LOG_CONTAINS_ALL_OF_HELPER(expected_messages, stmt, false)
86
87		// Validates that when stmt is executed, log messages containing substr and loglevel will be
88		// emitted. Escaped=true sets the behavior to function like the --log-format-escaped CLI flag.
89		// Failure message e.g.,
90		//
91		// Logs:
92		// [2018-04-12 05:51:00.245][7290192][debug][upstream] grpc_mux_impl.cc:160] Received gRPC
93		// [2018-04-12 05:51:00.246][7290192][warning][upstream] grpc_mux_impl.cc:63] Called bar
94		// [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:80] Sending foo
95		// Does NOT contain:
96		// 'warning', 'Too many sendDiscoveryRequest calls for baz’
97		// 'warning', 'Too man sendDiscoveryRequest calls for foo'
98		#define EXPECT_LOG_CONTAINS_ALL_OF_HELPER(expected_messages, stmt, escaped) \
99		do { \
100		ASSERT_FALSE(expected_messages.empty()) << "Expected messages cannot be empty."; \
101		::Envoy::Assert::resetEnvoyBugCountersForTest(); \
102		Envoy::LogLevelSetter save_levels(spdlog::level::trace); \
103		Envoy::Logger::DelegatingLogSinkSharedPtr sink_ptr = Envoy::Logger::Registry::getSink(); \
104		sink_ptr->setShouldEscape(escaped); \
105		Envoy::LogRecordingSink log_recorder(sink_ptr); \
106		stmt; \
107		auto messages = log_recorder.messages(); \
108		if (messages.empty()) { \
109		FAIL() << "Expected message(s), but NONE was recorded."; \
110		} \
111		Envoy::ExpectedLogMessages failed_expectations; \
112		for (const Envoy::StringPair& expected : expected_messages) { \
113		const auto log_message = \
114		std::find_if(messages.begin(), messages.end(), [&expected](const std::string& message) { \
115		return (message.find(expected.second) != std::string::npos) && \
116		(message.find(expected.first) != std::string::npos); \
117		}); \
118		if (log_message == messages.end()) { \
119		failed_expectations.push_back(expected); \
120		} \
121		} \
122		if (!failed_expectations.empty()) { \
123		std::string failed_message; \
124		absl::StrAppend(&failed_message, "\nLogs:\n ", absl::StrJoin(messages, " "), \
125		"\n Do NOT contain:\n"); \
126		for (const auto& expectation : failed_expectations) { \
127		absl::StrAppend(&failed_message, " '", expectation.first, "', '", expectation.second, \
128		"'\n"); \
129		} \
130		FAIL() << failed_message; \
131		} \
132		} while (false)
133
134		// Validates that when stmt is executed, log message containing substr and loglevel will NOT be
135		// emitted. Failure message e.g.,
136		//
137		// Logs:
138		// [2018-04-12 05:51:00.245][7290192][warning][upstream] grpc_mux_impl.cc:160] Received gRPC
139		// [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:63] Called bar
140		// Should NOT contain:
141		// 'warning', 'Received gRPC’
142		#define EXPECT_LOG_NOT_CONTAINS(loglevel, substr, stmt) \
143		do { \
144		Envoy::LogLevelSetter save_levels(spdlog::level::trace); \
145		Envoy::LogRecordingSink log_recorder(Envoy::Logger::Registry::getSink()); \
146		stmt; \
147		auto messages = log_recorder.messages(); \
148		for (const std::string& message : messages) { \
149		if ((message.find(substr) != std::string::npos) && \
150		(message.find(loglevel) != std::string::npos)) { \
151		FAIL() << "\nLogs:\n " << absl::StrJoin(messages, " ") << "\n Should NOT contain:\n '" \
152		<< loglevel << "', '" << substr "'\n"; \
153		} \
154		} \
155		} while (false)
156
157		// Validates that when stmt is executed, the supplied substring matches at least one log message.
158		// Failure message e.g.,
159		//
160		// Logs:
161		// [2018-04-12 05:51:00.245][7290192][debug][upstream] grpc_mux_impl.cc:160] Received gRPC
162		// [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:80] Sending foo
163		// Do NOT contain:
164		// 'warning', 'Too many sendDiscoveryRequest calls for baz’
165		#define EXPECT_LOG_CONTAINS(loglevel, substr, stmt) \
166		do { \
167		const Envoy::ExpectedLogMessages message{{loglevel, substr}}; \
168		EXPECT_LOG_CONTAINS_ALL_OF(message, stmt); \
169		} while (false)
170
171		// Validates that when stmt is executed, the supplied substring occurs exactly the specified
172		// number of times.
173		#define EXPECT_LOG_CONTAINS_N_TIMES(loglevel, substr, expected_occurrences, stmt) \
174		do { \
175		Envoy::LogLevelSetter save_levels(spdlog::level::trace); \
176		Envoy::LogRecordingSink log_recorder(Envoy::Logger::Registry::getSink()); \
177		stmt; \
178		auto messages = log_recorder.messages(); \
179		uint64_t actual_occurrences = 0; \
180		for (const std::string& message : messages) { \
181		if ((message.find(substr) != std::string::npos) && \
182		(message.find(loglevel) != std::string::npos)) { \
183		actual_occurrences++; \
184		} \
185		} \
186		EXPECT_EQ(expected_occurrences, actual_occurrences); \
187		} while (false)
188
189		// Validates that when stmt is executed, no logs will be emitted.
190		// Expected equality of these values:
191		// 0
192		// logs.size()
193		// Which is: 3
194		// Logs:
195		// [2018-04-12 05:51:00.245][7290192][debug][upstream] grpc_mux_impl.cc:160] Received gRPC
196		// [2018-04-12 05:51:00.246][7290192][trace][upstream] grpc_mux_impl.cc:80] Sending foo
197		#define EXPECT_NO_LOGS(stmt) \
198		do { \
199		Envoy::LogLevelSetter save_levels(spdlog::level::trace); \
200		Envoy::LogRecordingSink log_recorder(Envoy::Logger::Registry::getSink()); \
201		stmt; \
202		const std::vector<std::string> logs = log_recorder.messages(); \
203		ASSERT_EQ(0, logs.size()) << " Logs:\n " << absl::StrJoin(logs, " "); \
204		} while (false)
205
206		// Validates that when stmt is executed, the supplied substring is eventually logged.
207		// This both waits infinitely (not ideal) and walks the full log list every time (not ideal).
208		#define WAIT_FOR_LOG_CONTAINS(loglevel_raw, substr_raw, stmt) \
209		do { \
210		Envoy::LogLevelSetter save_levels(spdlog::level::trace); \
211		Envoy::Logger::DelegatingLogSinkSharedPtr sink_ptr = Envoy::Logger::Registry::getSink(); \
212		std::string loglevel = loglevel_raw; \
213		std::string substr = substr_raw; \
214		Envoy::LogRecordingSink log_recorder(sink_ptr); \
215		stmt; \
216		while (true) { \
217		auto messages = log_recorder.messages(); \
218		if (messages.empty()) { \
219		continue; \
220		} \
221		const auto log_message = std::find_if( \
222		messages.begin(), messages.end(), [&substr, loglevel](const std::string& message) { \
223		return (message.find(substr) != std::string::npos) && \
224		(message.find(loglevel) != std::string::npos); \
225		}); \
226		if (log_message != messages.end()) { \
227		break; \
228		} \
229		} \
230		} while (false)
231
232		} // namespace Envoy