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(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  
273  struct ScopedScheduler {
274      CScheduler scheduler{};
275  
276      ScopedScheduler()
277      {
278          scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); });
279      }
280      ~ScopedScheduler()
281      {
282          scheduler.stop();
283      }
284      void MockForwardAndSync(std::chrono::seconds duration)
285      {
286          scheduler.MockForward(duration);
287          std::promise<void> promise;
288          scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms);
289          promise.get_future().wait();
290      }
291      std::shared_ptr<BCLog::LogRateLimiter> GetLimiter(size_t max_bytes, std::chrono::seconds window)
292      {
293          auto sched_func = [this](auto func, auto w) {
294              scheduler.scheduleEvery(std::move(func), w);
295          };
296          return BCLog::LogRateLimiter::Create(sched_func, max_bytes, window);
297      }
298  };
299  
300  BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
301  {
302      uint64_t max_bytes{1024};
303      auto reset_window{1min};
304      ScopedScheduler scheduler{};
305      auto limiter_{scheduler.GetLimiter(max_bytes, reset_window)};
306      auto& limiter{*Assert(limiter_)};
307  
308      using Status = BCLog::LogRateLimiter::Status;
309      auto source_loc_1{SourceLocation{__func__}};
310      auto source_loc_2{SourceLocation{__func__}};
311  
312      // A fresh limiter should not have any suppressions
313      BOOST_CHECK(!limiter.SuppressionsActive());
314  
315      // Resetting an unused limiter is fine
316      limiter.Reset();
317      BOOST_CHECK(!limiter.SuppressionsActive());
318  
319      // No suppression should happen until more than max_bytes have been consumed
320      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes - 1, 'a')), Status::UNSUPPRESSED);
321      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::UNSUPPRESSED);
322      BOOST_CHECK(!limiter.SuppressionsActive());
323      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::NEWLY_SUPPRESSED);
324      BOOST_CHECK(limiter.SuppressionsActive());
325      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::STILL_SUPPRESSED);
326      BOOST_CHECK(limiter.SuppressionsActive());
327  
328      // Location 2  should not be affected by location 1's suppression
329      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
330      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, "a"), Status::NEWLY_SUPPRESSED);
331      BOOST_CHECK(limiter.SuppressionsActive());
332  
333      // After reset_window time has passed, all suppressions should be cleared.
334      scheduler.MockForwardAndSync(reset_window);
335  
336      BOOST_CHECK(!limiter.SuppressionsActive());
337      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
338      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
339  }
340  
341  BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
342  {
343      BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES);
344  
345      // Check that stats gets initialized correctly.
346      BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES);
347      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
348  
349      const uint64_t MESSAGE_SIZE{BCLog::RATELIMIT_MAX_BYTES / 2};
350      BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
351      BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE);
352      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
353  
354      BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
355      BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2);
356      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
357  
358      // Consuming more bytes after already having consumed RATELIMIT_MAX_BYTES should fail.
359      BOOST_CHECK(!stats.Consume(500));
360      BOOST_CHECK_EQUAL(stats.m_available_bytes, uint64_t{0});
361      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{500});
362  }
363  
364  namespace {
365  
366  enum class Location {
367      INFO_1,
368      INFO_2,
369      DEBUG_LOG,
370      INFO_NOLIMIT,
371  };
372  
373  void LogFromLocation(Location location, const std::string& message) {
374      switch (location) {
375      case Location::INFO_1:
376          LogInfo("%s\n", message);
377          return;
378      case Location::INFO_2:
379          LogInfo("%s\n", message);
380          return;
381      case Location::DEBUG_LOG:
382          LogDebug(BCLog::LogFlags::HTTP, "%s\n", message);
383          return;
384      case Location::INFO_NOLIMIT:
385          LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s\n", message);
386          return;
387      } // no default case, so the compiler can warn about missing cases
388      assert(false);
389  }
390  
391  /**
392   * For a given `location` and `message`, ensure that the on-disk debug log behaviour resembles what
393   * we'd expect it to be for `status` and `suppressions_active`.
394   */
395  void TestLogFromLocation(Location location, const std::string& message,
396                           BCLog::LogRateLimiter::Status status, bool suppressions_active,
397                           std::source_location source = std::source_location::current())
398  {
399      BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line());
400      using Status = BCLog::LogRateLimiter::Status;
401      if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error
402  
403      std::ofstream ofs(LogInstance().m_file_path.std_path(), std::ios::out | std::ios::trunc); // clear debug log
404      LogFromLocation(location, message);
405      auto log_lines{ReadDebugLogLines()};
406      BOOST_TEST_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n"));
407  
408      if (status == Status::STILL_SUPPRESSED) {
409          BOOST_CHECK_EQUAL(log_lines.size(), 0);
410          return;
411      }
412  
413      if (status == Status::NEWLY_SUPPRESSED) {
414          BOOST_REQUIRE_EQUAL(log_lines.size(), 2);
415          BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected"));
416          log_lines.erase(log_lines.begin());
417      }
418      BOOST_REQUIRE_EQUAL(log_lines.size(), 1);
419      auto& payload{log_lines.back()};
420      BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]"));
421      BOOST_CHECK(payload.ends_with(message));
422  }
423  
424  } // namespace
425  
426  BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
427  {
428      using Status = BCLog::LogRateLimiter::Status;
429      LogInstance().m_log_timestamps = false;
430      LogInstance().m_log_sourcelocations = false;
431      LogInstance().m_log_threadnames = false;
432      LogInstance().EnableCategory(BCLog::LogFlags::HTTP);
433  
434      constexpr int64_t line_length{1024};
435      constexpr int64_t num_lines{10};
436      constexpr int64_t bytes_quota{line_length * num_lines};
437      constexpr auto time_window{1h};
438  
439      ScopedScheduler scheduler{};
440      auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
441      LogInstance().SetRateLimiting(limiter);
442  
443      const std::string log_message(line_length - 1, 'a'); // subtract one for newline
444  
445      for (int i = 0; i < num_lines; ++i) {
446          TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
447      }
448      TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true);
449      TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true);
450      TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
451      {
452          scheduler.MockForwardAndSync(time_window);
453          BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
454      }
455      // Check that logging from previously suppressed location is unsuppressed again.
456      TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
457      // Check that conditional logging, and unconditional logging with should_ratelimit=false is
458      // not being ratelimited.
459      for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) {
460          for (int i = 0; i < num_lines + 2; ++i) {
461              TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
462          }
463      }
464  }
465  
466  BOOST_AUTO_TEST_SUITE_END()