/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/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::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: 2023-11-12 09:30

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