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_LogPrintStr, 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().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false);
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          BCLog::LogFlags category;
169          const auto trimmed_category_name = TrimString(category_name);
170          BOOST_REQUIRE(GetLogCategory(category, trimmed_category_name));
171          expected_category_names.emplace_back(category, trimmed_category_name);
172      }
173  
174      std::vector<std::string> expected;
175      for (const auto& [category, name] : expected_category_names) {
176          LogDebug(category, "foo: %s\n", "bar");
177          std::string expected_log = "[";
178          expected_log += name;
179          expected_log += "] foo: bar";
180          expected.push_back(expected_log);
181      }
182  
183      std::vector<std::string> log_lines{ReadDebugLogLines()};
184      BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
185  }
186  
187  BOOST_FIXTURE_TEST_CASE(logging_SeverityLevels, LogSetup)
188  {
189      LogInstance().SetLogLevel(BCLog::Level::Debug);
190      LogInstance().EnableCategory(BCLog::LogFlags::ALL);
191      LogInstance().SetCategoryLogLevel(/*category_str=*/"net", /*level_str=*/"info");
192  
193      // Global log level
194      LogInfo("info_%s", 1);
195      LogTrace(BCLog::HTTP, "trace_%s. This log level is lower than the global one.", 2);
196      LogDebug(BCLog::HTTP, "debug_%s", 3);
197      LogWarning("warn_%s", 4);
198      LogError("err_%s", 5);
199  
200      // Category-specific log level
201      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);
202  
203      std::vector<std::string> expected = {
204          "info_1",
205          "[http] debug_3",
206          "[warning] warn_4",
207          "[error] err_5",
208      };
209      std::vector<std::string> log_lines{ReadDebugLogLines()};
210      BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
211  }
212  
213  BOOST_FIXTURE_TEST_CASE(logging_Conf, LogSetup)
214  {
215      // Set global log level
216      {
217          ResetLogger();
218          ArgsManager args;
219          args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
220          const char* argv_test[] = {"bitcoind", "-loglevel=debug"};
221          std::string err;
222          BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
223  
224          auto result = init::SetLoggingLevel(args);
225          BOOST_REQUIRE(result);
226          BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
227      }
228  
229      // Set category-specific log level
230      {
231          ResetLogger();
232          ArgsManager args;
233          args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
234          const char* argv_test[] = {"bitcoind", "-loglevel=net:trace"};
235          std::string err;
236          BOOST_REQUIRE(args.ParseParameters(2, argv_test, err));
237  
238          auto result = init::SetLoggingLevel(args);
239          BOOST_REQUIRE(result);
240          BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::DEFAULT_LOG_LEVEL);
241  
242          const auto& category_levels{LogInstance().CategoryLevels()};
243          const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
244          BOOST_REQUIRE(net_it != category_levels.end());
245          BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
246      }
247  
248      // Set both global log level and category-specific log level
249      {
250          ResetLogger();
251          ArgsManager args;
252          args.AddArg("-loglevel", "...", ArgsManager::ALLOW_ANY, OptionsCategory::DEBUG_TEST);
253          const char* argv_test[] = {"bitcoind", "-loglevel=debug", "-loglevel=net:trace", "-loglevel=http:info"};
254          std::string err;
255          BOOST_REQUIRE(args.ParseParameters(4, argv_test, err));
256  
257          auto result = init::SetLoggingLevel(args);
258          BOOST_REQUIRE(result);
259          BOOST_CHECK_EQUAL(LogInstance().LogLevel(), BCLog::Level::Debug);
260  
261          const auto& category_levels{LogInstance().CategoryLevels()};
262          BOOST_CHECK_EQUAL(category_levels.size(), 2);
263  
264          const auto net_it{category_levels.find(BCLog::LogFlags::NET)};
265          BOOST_CHECK(net_it != category_levels.end());
266          BOOST_CHECK_EQUAL(net_it->second, BCLog::Level::Trace);
267  
268          const auto http_it{category_levels.find(BCLog::LogFlags::HTTP)};
269          BOOST_CHECK(http_it != category_levels.end());
270          BOOST_CHECK_EQUAL(http_it->second, BCLog::Level::Info);
271      }
272  }
273  
274  struct ScopedScheduler {
275      CScheduler scheduler{};
276  
277      ScopedScheduler()
278      {
279          scheduler.m_service_thread = std::thread([this] { scheduler.serviceQueue(); });
280      }
281      ~ScopedScheduler()
282      {
283          scheduler.stop();
284      }
285      void MockForwardAndSync(std::chrono::seconds duration)
286      {
287          scheduler.MockForward(duration);
288          std::promise<void> promise;
289          scheduler.scheduleFromNow([&promise] { promise.set_value(); }, 0ms);
290          promise.get_future().wait();
291      }
292      std::shared_ptr<BCLog::LogRateLimiter> GetLimiter(size_t max_bytes, std::chrono::seconds window)
293      {
294          auto sched_func = [this](auto func, auto w) {
295              scheduler.scheduleEvery(std::move(func), w);
296          };
297          return BCLog::LogRateLimiter::Create(sched_func, max_bytes, window);
298      }
299  };
300  
301  BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
302  {
303      uint64_t max_bytes{1024};
304      auto reset_window{1min};
305      ScopedScheduler scheduler{};
306      auto limiter_{scheduler.GetLimiter(max_bytes, reset_window)};
307      auto& limiter{*Assert(limiter_)};
308  
309      using Status = BCLog::LogRateLimiter::Status;
310      auto source_loc_1{SourceLocation{__func__}};
311      auto source_loc_2{SourceLocation{__func__}};
312  
313      // A fresh limiter should not have any suppressions
314      BOOST_CHECK(!limiter.SuppressionsActive());
315  
316      // Resetting an unused limiter is fine
317      limiter.Reset();
318      BOOST_CHECK(!limiter.SuppressionsActive());
319  
320      // No suppression should happen until more than max_bytes have been consumed
321      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes - 1, 'a')), Status::UNSUPPRESSED);
322      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::UNSUPPRESSED);
323      BOOST_CHECK(!limiter.SuppressionsActive());
324      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::NEWLY_SUPPRESSED);
325      BOOST_CHECK(limiter.SuppressionsActive());
326      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, "a"), Status::STILL_SUPPRESSED);
327      BOOST_CHECK(limiter.SuppressionsActive());
328  
329      // Location 2  should not be affected by location 1's suppression
330      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
331      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, "a"), Status::NEWLY_SUPPRESSED);
332      BOOST_CHECK(limiter.SuppressionsActive());
333  
334      // After reset_window time has passed, all suppressions should be cleared.
335      scheduler.MockForwardAndSync(reset_window);
336  
337      BOOST_CHECK(!limiter.SuppressionsActive());
338      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_1, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
339      BOOST_CHECK_EQUAL(limiter.Consume(source_loc_2, std::string(max_bytes, 'a')), Status::UNSUPPRESSED);
340  }
341  
342  BOOST_AUTO_TEST_CASE(logging_log_limit_stats)
343  {
344      BCLog::LogRateLimiter::Stats stats(BCLog::RATELIMIT_MAX_BYTES);
345  
346      // Check that stats gets initialized correctly.
347      BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES);
348      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
349  
350      const uint64_t MESSAGE_SIZE{BCLog::RATELIMIT_MAX_BYTES / 2};
351      BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
352      BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE);
353      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
354  
355      BOOST_CHECK(stats.Consume(MESSAGE_SIZE));
356      BOOST_CHECK_EQUAL(stats.m_available_bytes, BCLog::RATELIMIT_MAX_BYTES - MESSAGE_SIZE * 2);
357      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{0});
358  
359      // Consuming more bytes after already having consumed RATELIMIT_MAX_BYTES should fail.
360      BOOST_CHECK(!stats.Consume(500));
361      BOOST_CHECK_EQUAL(stats.m_available_bytes, uint64_t{0});
362      BOOST_CHECK_EQUAL(stats.m_dropped_bytes, uint64_t{500});
363  }
364  
365  namespace {
366  
367  enum class Location {
368      INFO_1,
369      INFO_2,
370      DEBUG_LOG,
371      INFO_NOLIMIT,
372  };
373  
374  void LogFromLocation(Location location, const std::string& message) {
375      switch (location) {
376      case Location::INFO_1:
377          LogInfo("%s\n", message);
378          return;
379      case Location::INFO_2:
380          LogInfo("%s\n", message);
381          return;
382      case Location::DEBUG_LOG:
383          LogDebug(BCLog::LogFlags::HTTP, "%s\n", message);
384          return;
385      case Location::INFO_NOLIMIT:
386          LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info, /*should_ratelimit=*/false, "%s\n", message);
387          return;
388      } // no default case, so the compiler can warn about missing cases
389      assert(false);
390  }
391  
392  /**
393   * For a given `location` and `message`, ensure that the on-disk debug log behaviour resembles what
394   * we'd expect it to be for `status` and `suppressions_active`.
395   */
396  void TestLogFromLocation(Location location, const std::string& message,
397                           BCLog::LogRateLimiter::Status status, bool suppressions_active,
398                           std::source_location source = std::source_location::current())
399  {
400      BOOST_TEST_INFO_SCOPE("TestLogFromLocation called from " << source.file_name() << ":" << source.line());
401      using Status = BCLog::LogRateLimiter::Status;
402      if (!suppressions_active) assert(status == Status::UNSUPPRESSED); // developer error
403  
404      std::ofstream ofs(LogInstance().m_file_path.std_path(), std::ios::out | std::ios::trunc); // clear debug log
405      LogFromLocation(location, message);
406      auto log_lines{ReadDebugLogLines()};
407      BOOST_TEST_INFO_SCOPE(log_lines.size() << " log_lines read: \n" << util::Join(log_lines, "\n"));
408  
409      if (status == Status::STILL_SUPPRESSED) {
410          BOOST_CHECK_EQUAL(log_lines.size(), 0);
411          return;
412      }
413  
414      if (status == Status::NEWLY_SUPPRESSED) {
415          BOOST_REQUIRE_EQUAL(log_lines.size(), 2);
416          BOOST_CHECK(log_lines[0].starts_with("[*] [warning] Excessive logging detected"));
417          log_lines.erase(log_lines.begin());
418      }
419      BOOST_REQUIRE_EQUAL(log_lines.size(), 1);
420      auto& payload{log_lines.back()};
421      BOOST_CHECK_EQUAL(suppressions_active, payload.starts_with("[*]"));
422      BOOST_CHECK(payload.ends_with(message));
423  }
424  
425  } // namespace
426  
427  BOOST_FIXTURE_TEST_CASE(logging_filesize_rate_limit, LogSetup)
428  {
429      using Status = BCLog::LogRateLimiter::Status;
430      LogInstance().m_log_timestamps = false;
431      LogInstance().m_log_sourcelocations = false;
432      LogInstance().m_log_threadnames = false;
433      LogInstance().EnableCategory(BCLog::LogFlags::HTTP);
434  
435      constexpr int64_t line_length{1024};
436      constexpr int64_t num_lines{10};
437      constexpr int64_t bytes_quota{line_length * num_lines};
438      constexpr auto time_window{1h};
439  
440      ScopedScheduler scheduler{};
441      auto limiter{scheduler.GetLimiter(bytes_quota, time_window)};
442      LogInstance().SetRateLimiting(limiter);
443  
444      const std::string log_message(line_length - 1, 'a'); // subtract one for newline
445  
446      for (int i = 0; i < num_lines; ++i) {
447          TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
448      }
449      TestLogFromLocation(Location::INFO_1, "a", Status::NEWLY_SUPPRESSED, /*suppressions_active=*/true);
450      TestLogFromLocation(Location::INFO_1, "b", Status::STILL_SUPPRESSED, /*suppressions_active=*/true);
451      TestLogFromLocation(Location::INFO_2, "c", Status::UNSUPPRESSED, /*suppressions_active=*/true);
452      {
453          scheduler.MockForwardAndSync(time_window);
454          BOOST_CHECK(ReadDebugLogLines().back().starts_with("[warning] Restarting logging"));
455      }
456      // Check that logging from previously suppressed location is unsuppressed again.
457      TestLogFromLocation(Location::INFO_1, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
458      // Check that conditional logging, and unconditional logging with should_ratelimit=false is
459      // not being ratelimited.
460      for (Location location : {Location::DEBUG_LOG, Location::INFO_NOLIMIT}) {
461          for (int i = 0; i < num_lines + 2; ++i) {
462              TestLogFromLocation(location, log_message, Status::UNSUPPRESSED, /*suppressions_active=*/false);
463          }
464      }
465  }
466  
467  BOOST_AUTO_TEST_SUITE_END()