logging_tests.cpp
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 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.std_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 LogInfo("Sentinel log to reopen log file"); 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[] = {"bitcoind", "-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[] = {"bitcoind", "-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[] = {"bitcoind", "-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_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()