Branch data Line data Source code
1 : : // Copyright (c) 2019-2022 The Bitcoin Core developers
2 : : // Distributed under the MIT software license, see the accompanying
3 : : // file COPYING or http://www.opensource.org/licenses/mit-license.php.
4 : :
5 : : #include <init/common.h>
6 : : #include <logging.h>
7 : : #include <logging/timer.h>
8 : : #include <scheduler.h>
9 : : #include <test/util/logging.h>
10 : : #include <test/util/setup_common.h>
11 : : #include <tinyformat.h>
12 : : #include <util/fs.h>
13 : : #include <util/fs_helpers.h>
14 : : #include <util/string.h>
15 : :
16 : : #include <chrono>
17 : : #include <fstream>
18 : : #include <future>
19 : : #include <ios>
20 : : #include <iostream>
21 : : #include <source_location>
22 : : #include <string>
23 : : #include <unordered_map>
24 : : #include <utility>
25 : : #include <vector>
26 : :
27 : : #include <boost/test/unit_test.hpp>
28 : :
29 : : using util::SplitString;
30 : : using util::TrimString;
31 : :
32 : : BOOST_FIXTURE_TEST_SUITE(logging_tests, BasicTestingSetup)
33 : :
34 : 3 : static void ResetLogger()
35 : : {
36 : 3 : LogInstance().SetLogLevel(BCLog::DEFAULT_LOG_LEVEL);
37 [ + - ]: 3 : LogInstance().SetCategoryLogLevel({});
38 : 3 : }
39 : :
40 : 44 : static std::vector<std::string> ReadDebugLogLines()
41 : : {
42 : 44 : std::vector<std::string> lines;
43 [ + - + - ]: 44 : std::ifstream ifs{LogInstance().m_file_path};
44 [ + + ]: 176 : for (std::string line; std::getline(ifs, line);) {
45 [ + - + - ]: 220 : lines.push_back(std::move(line));
46 : 0 : }
47 : 44 : return lines;
48 : 44 : }
49 : :
50 : : struct LogSetup : public BasicTestingSetup {
51 : : fs::path prev_log_path;
52 : : fs::path tmp_log_path;
53 : : bool prev_reopen_file;
54 : : bool prev_print_to_file;
55 : : bool prev_log_timestamps;
56 : : bool prev_log_threadnames;
57 : : bool prev_log_sourcelocations;
58 : : std::unordered_map<BCLog::LogFlags, BCLog::Level> prev_category_levels;
59 : : BCLog::Level prev_log_level;
60 : : BCLog::CategoryMask prev_category_mask;
61 : :
62 [ + - ]: 7 : LogSetup() : prev_log_path{LogInstance().m_file_path},
63 [ + - + - ]: 14 : tmp_log_path{m_args.GetDataDirBase() / "tmp_debug.log"},
64 [ + - + - ]: 7 : prev_reopen_file{LogInstance().m_reopen_file},
65 [ + - ]: 7 : prev_print_to_file{LogInstance().m_print_to_file},
66 [ + - ]: 7 : prev_log_timestamps{LogInstance().m_log_timestamps},
67 [ + - ]: 7 : prev_log_threadnames{LogInstance().m_log_threadnames},
68 [ + - ]: 7 : prev_log_sourcelocations{LogInstance().m_log_sourcelocations},
69 [ + - + - ]: 7 : prev_category_levels{LogInstance().CategoryLevels()},
70 [ + - + - ]: 7 : prev_log_level{LogInstance().LogLevel()},
71 [ + - + - : 21 : prev_category_mask{LogInstance().GetCategoryMask()}
+ - + - ]
72 : : {
73 [ + - + - ]: 7 : LogInstance().m_file_path = tmp_log_path;
74 [ + - + - ]: 7 : LogInstance().m_reopen_file = true;
75 [ + - ]: 7 : LogInstance().m_print_to_file = true;
76 [ + - ]: 7 : LogInstance().m_log_timestamps = false;
77 [ + - ]: 7 : LogInstance().m_log_threadnames = false;
78 : :
79 : : // Prevent tests from failing when the line number of the logs changes.
80 [ + - ]: 7 : LogInstance().m_log_sourcelocations = false;
81 : :
82 [ + - + - ]: 7 : LogInstance().SetLogLevel(BCLog::Level::Debug);
83 [ + - + - ]: 7 : LogInstance().DisableCategory(BCLog::LogFlags::ALL);
84 [ + - + - ]: 7 : LogInstance().SetCategoryLogLevel({});
85 [ + - + - ]: 7 : LogInstance().SetRateLimiting(nullptr);
86 : 7 : }
87 : :
88 : 7 : ~LogSetup()
89 : : {
90 : 7 : LogInstance().m_file_path = prev_log_path;
91 : 7 : LogInfo("Sentinel log to reopen log file");
92 : 7 : LogInstance().m_print_to_file = prev_print_to_file;
93 : 7 : LogInstance().m_reopen_file = prev_reopen_file;
94 : 7 : LogInstance().m_log_timestamps = prev_log_timestamps;
95 : 7 : LogInstance().m_log_threadnames = prev_log_threadnames;
96 : 7 : LogInstance().m_log_sourcelocations = prev_log_sourcelocations;
97 : 7 : LogInstance().SetLogLevel(prev_log_level);
98 : 7 : LogInstance().SetCategoryLogLevel(prev_category_levels);
99 [ - + ]: 7 : LogInstance().SetRateLimiting(nullptr);
100 : 7 : LogInstance().DisableCategory(BCLog::LogFlags::ALL);
101 : 7 : LogInstance().EnableCategory(BCLog::LogFlags{prev_category_mask});
102 : 21 : }
103 : : };
104 : :
105 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_timer)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
106 : : {
107 [ + - + - ]: 2 : auto micro_timer = BCLog::Timer<std::chrono::microseconds>("tests", "end_msg");
108 [ + - ]: 1 : const std::string_view result_prefix{"tests: msg ("};
109 [ + - + - : 1 : BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix);
+ - + - +
- ]
110 : 1 : }
111 : :
112 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
113 : : {
114 : 1 : LogInstance().m_log_sourcelocations = true;
115 : :
116 : 12 : struct Case {
117 : : std::string msg;
118 : : BCLog::LogFlags category;
119 : : BCLog::Level level;
120 : : std::string prefix;
121 : : std::source_location loc;
122 : : };
123 : :
124 : 1 : std::vector<Case> cases = {
125 : : {"foo1: bar1", BCLog::NET, BCLog::Level::Debug, "[net] ", std::source_location::current()},
126 : : {"foo2: bar2", BCLog::NET, BCLog::Level::Info, "[net:info] ", std::source_location::current()},
127 : : {"foo3: bar3", BCLog::ALL, BCLog::Level::Debug, "[debug] ", std::source_location::current()},
128 : : {"foo4: bar4", BCLog::ALL, BCLog::Level::Info, "", std::source_location::current()},
129 : : {"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ", std::source_location::current()},
130 : : {"foo6: bar6", BCLog::NONE, BCLog::Level::Info, "", std::source_location::current()},
131 [ - + + + : 7 : };
- - ]
132 : :
133 : 1 : std::vector<std::string> expected;
134 [ + + ]: 7 : for (auto& [msg, category, level, prefix, loc] : cases) {
135 [ + - + - : 30 : expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name(), prefix, msg));
+ - + - +
- ]
136 [ + - - + : 6 : LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false);
+ - ]
137 : : }
138 [ + - ]: 1 : std::vector<std::string> log_lines{ReadDebugLogLines()};
139 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
140 [ + - + - : 2 : }
+ - + - +
- + - + -
+ - + - +
- + - + -
- - ]
141 : :
142 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacrosDeprecated, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
143 : : {
144 : 1 : LogInstance().EnableCategory(BCLog::NET);
145 : 1 : LogPrintf("foo5: %s\n", "bar5");
146 [ - + ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Trace, "foo4: %s\n", "bar4"); // not logged
147 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo7: %s\n", "bar7");
148 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Info, "foo8: %s\n", "bar8");
149 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo9: %s\n", "bar9");
150 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo10: %s\n", "bar10");
151 : 1 : std::vector<std::string> log_lines{ReadDebugLogLines()};
152 : 1 : std::vector<std::string> expected = {
153 : : "foo5: bar5",
154 : : "[net] foo7: bar7",
155 : : "[net:info] foo8: bar8",
156 : : "[net:warning] foo9: bar9",
157 : : "[net:error] foo10: bar10",
158 [ + - ]: 1 : };
159 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
160 : 1 : }
161 : :
162 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
163 : : {
164 : 1 : LogInstance().EnableCategory(BCLog::NET);
165 [ - + ]: 1 : LogTrace(BCLog::NET, "foo6: %s", "bar6"); // not logged
166 [ + - ]: 1 : LogDebug(BCLog::NET, "foo7: %s", "bar7");
167 : 1 : LogInfo("foo8: %s", "bar8");
168 : 1 : LogWarning("foo9: %s", "bar9");
169 : 1 : LogError("foo10: %s", "bar10");
170 : 1 : std::vector<std::string> log_lines{ReadDebugLogLines()};
171 : 1 : std::vector<std::string> expected = {
172 : : "[net] foo7: bar7",
173 : : "foo8: bar8",
174 : : "[warning] foo9: bar9",
175 : : "[error] foo10: bar10",
176 [ + - ]: 1 : };
177 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
178 : 1 : }
179 : :
180 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_LogPrintMacros_CategoryName, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
181 : : {
182 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::ALL);
183 : 1 : const auto concatenated_category_names = LogInstance().LogCategoriesString();
184 : 1 : std::vector<std::pair<BCLog::LogFlags, std::string>> expected_category_names;
185 [ - + + - ]: 1 : const auto category_names = SplitString(concatenated_category_names, ',');
186 [ + + ]: 29 : for (const auto& category_name : category_names) {
187 : 28 : BCLog::LogFlags category;
188 [ - + + - ]: 28 : const auto trimmed_category_name = TrimString(category_name);
189 [ + - - + : 56 : BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name));
+ - + - +
- ]
190 [ + - ]: 28 : expected_category_names.emplace_back(category, trimmed_category_name);
191 : 28 : }
192 : :
193 : 1 : std::vector<std::string> expected;
194 [ + - + + ]: 29 : for (const auto& [category, name] : expected_category_names) {
195 [ + - + - : 28 : LogDebug(category, "foo: %s\n", "bar");
+ - ]
196 [ + - ]: 28 : std::string expected_log = "[";
197 [ - + ]: 28 : expected_log += name;
198 [ + - ]: 28 : expected_log += "] foo: bar";
199 [ + - ]: 28 : expected.push_back(expected_log);
200 : 28 : }
201 : :
202 [ + - ]: 1 : std::vector<std::string> log_lines{ReadDebugLogLines()};
203 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
204 : 1 : }
205 : :
206 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
207 : : {
208 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::ALL);
209 : 1 : LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
210 : :
211 : : // Global log level
212 [ + - ]: 1 : LogPrintLevel(BCLog::HTTP, BCLog::Level::Info, "foo1: %s\n", "bar1");
213 [ - + ]: 1 : LogPrintLevel(BCLog::MEMPOOL, BCLog::Level::Trace, "foo2: %s. This log level is lower than the global one.\n", "bar2");
214 [ + - ]: 1 : LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Warning, "foo3: %s\n", "bar3");
215 [ + - ]: 1 : LogPrintLevel(BCLog::RPC, BCLog::Level::Error, "foo4: %s\n", "bar4");
216 : :
217 : : // Category-specific log level
218 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Warning, "foo5: %s\n", "bar5");
219 [ - + ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Debug, "foo6: %s. This log level is the same as the global one but lower than the category-specific one, which takes precedence. \n", "bar6");
220 [ + - ]: 1 : LogPrintLevel(BCLog::NET, BCLog::Level::Error, "foo7: %s\n", "bar7");
221 : :
222 : 1 : std::vector<std::string> expected = {
223 : : "[http:info] foo1: bar1",
224 : : "[validation:warning] foo3: bar3",
225 : : "[rpc:error] foo4: bar4",
226 : : "[net:warning] foo5: bar5",
227 : : "[net:error] foo7: bar7",
228 : 1 : };
229 [ + - ]: 1 : std::vector<std::string> log_lines{ReadDebugLogLines()};
230 [ + - + - : 2 : BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
+ - ]
231 : 1 : }
232 : :
233 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
234 : : {
235 : : // Set global log level
236 : 1 : {
237 : 1 : ResetLogger();
238 : 1 : ArgsManager args;
239 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
240 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
241 [ + - ]: 1 : std::string err;
242 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
+ - + - ]
243 : :
244 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
245 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
246 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
+ - ]
247 : 1 : }
248 : :
249 : : // Set category-specific log level
250 : 1 : {
251 : 1 : ResetLogger();
252 : 1 : ArgsManager args;
253 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
254 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
255 [ + - ]: 1 : std::string err;
256 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
+ - + - ]
257 : :
258 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
259 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
260 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL);
+ - ]
261 : :
262 [ + - + - ]: 1 : const auto& category_levels{LogInstance().CategoryLevels()};
263 : 1 : const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
264 [ + - + - : 3 : BOOST_REQUIRE(net_it != category_levels.end());
+ - + - ]
265 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
266 : 1 : }
267 : :
268 : : // Set both global log level and category-specific log level
269 : 1 : {
270 : 1 : ResetLogger();
271 : 1 : ArgsManager args;
272 [ + - + - : 2 : args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
+ - ]
273 : 1 : const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
274 [ + - ]: 1 : std::string err;
275 [ + - + - : 2 : BOOST_REQUIRE(args.ParseParameters(4, argv_test, err));
+ - + - ]
276 : :
277 [ + - ]: 1 : auto result = init::SetLoggingLevel(args);
278 [ + - + - : 2 : BOOST_REQUIRE(result);
+ - ]
279 [ + - + - : 1 : BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
+ - ]
280 : :
281 [ + - + - ]: 2 : const auto& category_levels{LogInstance().CategoryLevels()};
282 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(category_levels.size(), 2);
283 : :
284 : 1 : const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
285 [ + - + - : 3 : BOOST_CHECK(net_it != category_levels.end());
+ - + - ]
286 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
287 : :
288 : 1 : const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
289 [ + - + - : 3 : BOOST_CHECK(http_it != category_levels.end());
+ - + - ]
290 [ + - + - ]: 1 : BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
291 : 1 : }
292 : 1 : }
293 : :
294 : : struct ScopedScheduler {
295 : : CScheduler scheduler{};
296 : :
297 : 2 : ScopedScheduler()
298 : 2 : {
299 [ + - ]: 4 : scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); });
300 : 2 : }
301 : 2 : ~ScopedScheduler()
302 : : {
303 : 0 : scheduler.stop();
304 : 2 : }
305 : 2 : void MockForwardAndSync(std::chrono::seconds duration)
306 : : {
307 : 2 : scheduler.MockForward(duration);
308 : 2 : std::promise<void> promise;
309 [ + - ]: 4 : scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms);
310 [ + - + - ]: 4 : promise.get_future().wait();
311 : 2 : }
312 : 2 : std::shared_ptr<BCLog::LogRateLimiter> GetLimiter(size_t max_bytes, std::chrono::seconds window)
313 : : {
314 : 4 : auto sched_func = [this](auto func, auto w) {
315 [ + - ]: 2 : scheduler.scheduleEvery(std::move(func), w);
316 : 2 : };
317 [ + - ]: 4 : return BCLog::LogRateLimiter::Create(sched_func, max_bytes, window);
318 : : }
319 : : };
320 : :
321 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
322 : : {
323 : 1 : uint64_t max_bytes{1024};
324 : 1 : auto reset_window{1min};
325 : 1 : ScopedScheduler scheduler{};
326 [ + - ]: 1 : auto limiter_{scheduler.GetLimiter(max_bytes, reset_window)};
327 [ + - + - ]: 1 : auto& limiter{*Assert(limiter_)};
328 : :
329 : 1 : using Status = BCLog::LogRateLimiter::Status;
330 : 1 : auto source_loc_1{std::source_location::current()};
331 : 1 : auto source_loc_2{std::source_location::current()};
332 : :
333 : : // A fresh limiter should not have any suppressions
334 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
335 : :
336 : : // Resetting an unused limiter is fine
337 [ + - ]: 1 : limiter.Reset();
338 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
339 : :
340 : : // No suppression should happen until more than max_bytes have been consumed
341 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes - 1, 'a')), Status::UNSUPPRESSED);
+ - + - ]
342 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::UNSUPPRESSED);
+ - + - ]
343 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
344 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::NEWLY_SUPPRESSED);
+ - + - ]
345 [ + - + - : 2 : BOOST_CHECK(limiter.SuppressionsActive());
+ - ]
346 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::STILL_SUPPRESSED);
+ - + - ]
347 [ + - + - : 2 : BOOST_CHECK(limiter.SuppressionsActive());
+ - ]
348 : :
349 : : // Location 2 should not be affected by location 1's suppression
350 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
+ - + - ]
351 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, "a"), Status::NEWLY_SUPPRESSED);
+ - + - ]
352 [ + - + - ]: 2 : BOOST_CHECK(limiter.SuppressionsActive());
353 : :
354 : : // After reset_window time has passed, all suppressions should be cleared.
355 [ + - ]: 1 : scheduler.MockForwardAndSync(reset_window);
356 : :
357 [ + - + - : 2 : BOOST_CHECK(!limiter.SuppressionsActive());
+ - ]
358 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
+ - + - ]
359 [ + - + - : 1 : BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
+ - + - +
- ]
360 : 2 : }
361 : :
362 [ + - + - : 7 : BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
363 : : {
364 : 1 : BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES);
365 : :
366 : : // Check that stats gets initialized correctly.
367 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES);
368 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
369 : :
370 : 1 : const uint64_t MESSAGE_SIZE{BCLog::RATELIMIT_MAX_BYTES / 2};
371 [ + - + - ]: 2 : BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
372 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE);
373 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
374 : :
375 [ + - + - ]: 2 : BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
376 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2);
377 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
378 : :
379 : : // Consuming more bytes after already having consumed RATELIMIT_MAX_BYTES should fail.
380 [ + - + - ]: 2 : BOOST_CHECK(!stats.Consume(500));
381 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_available_bytes, uint64_t{0});
382 [ + - ]: 1 : BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{500});
383 : 1 : }
384 : :
385 : : namespace {
386 : :
387 : : enum class Location {
388 : : INFO_1,
389 : : INFO_2,
390 : : DEBUG_LOG,
391 : : INFO_NOLIMIT,
392 : : };
393 : :
394 : 38 : void LogFromLocation(Location location, const std::string& message) {
395 [ + + + + : 38 : switch (location) {
- ]
396 : 13 : case Location::INFO_1:
397 : 13 : LogInfo("%s\n", message);
398 : 13 : return;
399 : 1 : case Location::INFO_2:
400 : 1 : LogInfo("%s\n", message);
401 : 1 : return;
402 : 12 : case Location::DEBUG_LOG:
403 [ + - ]: 12 : LogDebug(BCLog::LogFlags::HTTP, "%s\n", message);
404 : : return;
405 : 12 : case Location::INFO_NOLIMIT:
406 : 12 : LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s\n", message);
407 : 12 : return;
408 : : } // no default case, so the compiler can warn about missing cases
409 : 0 : assert(false);
410 : : }
411 : :
412 : : /**
413 : : * For a given `location` and `message`, ensure that the on-disk debug log behaviour resembles what
414 : : * we'd expect it to be for `status` and `suppressions_active`.
415 : : */
416 : 38 : void TestLogFromLocation(Location location, const std::string& message,
417 : : BCLog::LogRateLimiter::Status status, bool suppressions_active,
418 : : std::source_location source = std::source_location::current())
419 : : {
420 [ + - + - : 151 : BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line());
+ - ]
421 : 38 : using Status = BCLog::LogRateLimiter::Status;
422 [ + + - + ]: 38 : if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error
423 : :
424 [ + - + - ]: 38 : std::ofstream ofs(LogInstance().m_file_path, std::ios::out | std::ios::trunc); // clear debug log
425 [ + - ]: 38 : LogFromLocation(location, message);
426 [ + - ]: 38 : auto log_lines{ReadDebugLogLines()};
427 [ - + + - : 38 : BOOST_TEST_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n"));
+ - + + ]
428 : :
429 [ + + ]: 38 : if (status == Status::STILL_SUPPRESSED) {
430 [ + - - + : 1 : BOOST_CHECK_EQUAL(log_lines.size(), 0);
+ - ]
431 : 1 : return;
432 : : }
433 : :
434 [ + + ]: 37 : if (status == Status::NEWLY_SUPPRESSED) {
435 [ + - - + : 1 : BOOST_REQUIRE_EQUAL(log_lines.size(), 2);
+ - ]
436 [ + - - + : 2 : BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected"));
+ - ]
437 : 1 : log_lines.erase(log_lines.begin());
438 : : }
439 [ + - - + : 37 : BOOST_REQUIRE_EQUAL(log_lines.size(), 1);
+ - ]
440 : 37 : auto& payload{log_lines.back()};
441 [ + - - + : 37 : BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]"));
+ - ]
442 [ + - - + : 74 : BOOST_CHECK(payload.ends_with(message));
- + + - ]
443 : 38 : }
444 : :
445 : : } // namespace
446 : :
447 [ + - + - : 7 : BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
+ - + - -
+ + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- + - + -
+ - + - +
- + - - +
+ - + - +
- + - + -
+ - - + +
- ]
448 : : {
449 : 1 : using Status = BCLog::LogRateLimiter::Status;
450 : 1 : LogInstance().m_log_timestamps = false;
451 : 1 : LogInstance().m_log_sourcelocations = false;
452 : 1 : LogInstance().m_log_threadnames = false;
453 : 1 : LogInstance().EnableCategory(BCLog::LogFlags::HTTP);
454 : :
455 : 1 : constexpr int64_t line_length{1024};
456 : 1 : constexpr int64_t num_lines{10};
457 : 1 : constexpr int64_t bytes_quota{line_length * num_lines};
458 : 1 : constexpr auto time_window{1h};
459 : :
460 : 1 : ScopedScheduler scheduler{};
461 [ + - ]: 1 : auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
462 [ + - + - : 2 : LogInstance().SetRateLimiting(limiter);
+ - ]
463 : :
464 [ + - ]: 1 : const std::string log_message(line_length - 1, 'a'); // subtract one for newline
465 : :
466 [ + + ]: 11 : for (int i = 0; i < num_lines; ++i) {
467 [ + - ]: 10 : TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
468 : : }
469 [ + - + - ]: 1 : TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true);
470 [ + - + - ]: 1 : TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true);
471 [ + - + - ]: 1 : TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
472 : 1 : {
473 [ + - ]: 1 : scheduler.MockForwardAndSync(time_window);
474 [ + - + - : 2 : BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
- + + - +
- ]
475 : : }
476 : : // Check that logging from previously suppressed location is unsuppressed again.
477 [ + - ]: 1 : TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
478 : : // Check that conditional logging, and unconditional logging with should_ratelimit=false is
479 : : // not being ratelimited.
480 [ + + ]: 3 : for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) {
481 [ + + ]: 26 : for (int i = 0; i < num_lines + 2; ++i) {
482 [ + - ]: 24 : TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
483 : : }
484 : : }
485 [ + - ]: 3 : }
486 : :
487 : : BOOST_AUTO_TEST_SUITE_END()
|
