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