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