1  // Copyright (c) 2009-2010 Satoshi Nakamoto
  2  // Copyright (c) 2009-present The Bitcoin Core developers
  3  // Distributed under the MIT software license, see the accompanying
  4  // file COPYING or http://www.opensource.org/licenses/mit-license.php.
  5  
  6  #include <logging.h>
  7  #include <memusage.h>
  8  #include <util/check.h>
  9  #include <util/fs.h>
 10  #include <util/string.h>
 11  #include <util/threadnames.h>
 12  #include <util/time.h>
 13  
 14  #include <array>
 15  #include <cstring>
 16  #include <map>
 17  #include <optional>
 18  #include <utility>
 19  
 20  using util::Join;
 21  using util::RemovePrefixView;
 22  
 23  const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
 24  constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
 25  
 26  BCLog::Logger& LogInstance()
 27  {
 28  /**
 29   * NOTE: the logger instances is leaked on exit. This is ugly, but will be
 30   * cleaned up by the OS/libc. Defining a logger as a global object doesn't work
 31   * since the order of destruction of static/global objects is undefined.
 32   * Consider if the logger gets destroyed, and then some later destructor calls
 33   * LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to
 34   * access the logger. When the shutdown sequence is fully audited and tested,
 35   * explicit destruction of these objects can be implemented by changing this
 36   * from a raw pointer to a std::unique_ptr.
 37   * Since the ~Logger() destructor is never called, the Logger class and all
 38   * its subclasses must have implicitly-defined destructors.
 39   *
 40   * This method of initialization was originally introduced in
 41   * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
 42   */
 43      static BCLog::Logger* g_logger{new BCLog::Logger()};
 44      return *g_logger;
 45  }
 46  
 47  bool fLogIPs = DEFAULT_LOGIPS;
 48  
 49  static int FileWriteStr(std::string_view str, FILE *fp)
 50  {
 51      return fwrite(str.data(), 1, str.size(), fp);
 52  }
 53  
 54  bool BCLog::Logger::StartLogging()
 55  {
 56      StdLockGuard scoped_lock(m_cs);
 57  
 58      assert(m_buffering);
 59      assert(m_fileout == nullptr);
 60  
 61      if (m_print_to_file) {
 62          assert(!m_file_path.empty());
 63          m_fileout = fsbridge::fopen(m_file_path, "a");
 64          if (!m_fileout) {
 65              return false;
 66          }
 67  
 68          setbuf(m_fileout, nullptr); // unbuffered
 69  
 70          // Add newlines to the logfile to distinguish this execution from the
 71          // last one.
 72          FileWriteStr("\n\n\n\n\n", m_fileout);
 73      }
 74  
 75      // dump buffered messages from before we opened the log
 76      m_buffering = false;
 77      if (m_buffer_lines_discarded > 0) {
 78          LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info, /*should_ratelimit=*/false);
 79      }
 80      while (!m_msgs_before_open.empty()) {
 81          const auto& buflog = m_msgs_before_open.front();
 82          std::string s{buflog.str};
 83          FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime);
 84          m_msgs_before_open.pop_front();
 85  
 86          if (m_print_to_file) FileWriteStr(s, m_fileout);
 87          if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
 88          for (const auto& cb : m_print_callbacks) {
 89              cb(s);
 90          }
 91      }
 92      m_cur_buffer_memusage = 0;
 93      if (m_print_to_console) fflush(stdout);
 94  
 95      return true;
 96  }
 97  
 98  void BCLog::Logger::DisconnectTestLogger()
 99  {
100      StdLockGuard scoped_lock(m_cs);
101      m_buffering = true;
102      if (m_fileout != nullptr) fclose(m_fileout);
103      m_fileout = nullptr;
104      m_print_callbacks.clear();
105      m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
106      m_cur_buffer_memusage = 0;
107      m_buffer_lines_discarded = 0;
108      m_msgs_before_open.clear();
109  }
110  
111  void BCLog::Logger::DisableLogging()
112  {
113      {
114          StdLockGuard scoped_lock(m_cs);
115          assert(m_buffering);
116          assert(m_print_callbacks.empty());
117      }
118      m_print_to_file = false;
119      m_print_to_console = false;
120      StartLogging();
121  }
122  
123  void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
124  {
125      m_categories |= flag;
126  }
127  
128  bool BCLog::Logger::EnableCategory(std::string_view str)
129  {
130      BCLog::LogFlags flag;
131      if (!GetLogCategory(flag, str)) return false;
132      EnableCategory(flag);
133      return true;
134  }
135  
136  void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
137  {
138      m_categories &= ~flag;
139  }
140  
141  bool BCLog::Logger::DisableCategory(std::string_view str)
142  {
143      BCLog::LogFlags flag;
144      if (!GetLogCategory(flag, str)) return false;
145      DisableCategory(flag);
146      return true;
147  }
148  
149  bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
150  {
151      return (m_categories.load(std::memory_order_relaxed) & category) != 0;
152  }
153  
154  bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
155  {
156      // Log messages at Info, Warning and Error level unconditionally, so that
157      // important troubleshooting information doesn't get lost.
158      if (level >= BCLog::Level::Info) return true;
159  
160      if (!WillLogCategory(category)) return false;
161  
162      StdLockGuard scoped_lock(m_cs);
163      const auto it{m_category_log_levels.find(category)};
164      return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
165  }
166  
167  bool BCLog::Logger::DefaultShrinkDebugFile() const
168  {
169      return m_categories == BCLog::NONE;
170  }
171  
172  static const std::map<std::string, BCLog::LogFlags, std::less<>> LOG_CATEGORIES_BY_STR{
173      {"net", BCLog::NET},
174      {"tor", BCLog::TOR},
175      {"mempool", BCLog::MEMPOOL},
176      {"http", BCLog::HTTP},
177      {"bench", BCLog::BENCH},
178      {"zmq", BCLog::ZMQ},
179      {"walletdb", BCLog::WALLETDB},
180      {"rpc", BCLog::RPC},
181      {"estimatefee", BCLog::ESTIMATEFEE},
182      {"addrman", BCLog::ADDRMAN},
183      {"selectcoins", BCLog::SELECTCOINS},
184      {"reindex", BCLog::REINDEX},
185      {"cmpctblock", BCLog::CMPCTBLOCK},
186      {"rand", BCLog::RAND},
187      {"prune", BCLog::PRUNE},
188      {"proxy", BCLog::PROXY},
189      {"mempoolrej", BCLog::MEMPOOLREJ},
190      {"libevent", BCLog::LIBEVENT},
191      {"coindb", BCLog::COINDB},
192      {"qt", BCLog::QT},
193      {"leveldb", BCLog::LEVELDB},
194      {"validation", BCLog::VALIDATION},
195      {"i2p", BCLog::I2P},
196      {"ipc", BCLog::IPC},
197  #ifdef DEBUG_LOCKCONTENTION
198      {"lock", BCLog::LOCK},
199  #endif
200      {"blockstorage", BCLog::BLOCKSTORAGE},
201      {"txreconciliation", BCLog::TXRECONCILIATION},
202      {"scan", BCLog::SCAN},
203      {"txpackages", BCLog::TXPACKAGES},
204      {"kernel", BCLog::KERNEL},
205  };
206  
207  static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
208      // Swap keys and values from LOG_CATEGORIES_BY_STR.
209      [](const auto& in) {
210          std::unordered_map<BCLog::LogFlags, std::string> out;
211          for (const auto& [k, v] : in) {
212              const bool inserted{out.emplace(v, k).second};
213              assert(inserted);
214          }
215          return out;
216      }(LOG_CATEGORIES_BY_STR)
217  };
218  
219  bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str)
220  {
221      if (str.empty() || str == "1" || str == "all") {
222          flag = BCLog::ALL;
223          return true;
224      }
225      auto it = LOG_CATEGORIES_BY_STR.find(str);
226      if (it != LOG_CATEGORIES_BY_STR.end()) {
227          flag = it->second;
228          return true;
229      }
230      return false;
231  }
232  
233  std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
234  {
235      switch (level) {
236      case BCLog::Level::Trace:
237          return "trace";
238      case BCLog::Level::Debug:
239          return "debug";
240      case BCLog::Level::Info:
241          return "info";
242      case BCLog::Level::Warning:
243          return "warning";
244      case BCLog::Level::Error:
245          return "error";
246      }
247      assert(false);
248  }
249  
250  static std::string LogCategoryToStr(BCLog::LogFlags category)
251  {
252      if (category == BCLog::ALL) {
253          return "all";
254      }
255      auto it = LOG_CATEGORIES_BY_FLAG.find(category);
256      assert(it != LOG_CATEGORIES_BY_FLAG.end());
257      return it->second;
258  }
259  
260  static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str)
261  {
262      if (level_str == "trace") {
263          return BCLog::Level::Trace;
264      } else if (level_str == "debug") {
265          return BCLog::Level::Debug;
266      } else if (level_str == "info") {
267          return BCLog::Level::Info;
268      } else if (level_str == "warning") {
269          return BCLog::Level::Warning;
270      } else if (level_str == "error") {
271          return BCLog::Level::Error;
272      } else {
273          return std::nullopt;
274      }
275  }
276  
277  std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
278  {
279      std::vector<LogCategory> ret;
280      ret.reserve(LOG_CATEGORIES_BY_STR.size());
281      for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
282          ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
283      }
284      return ret;
285  }
286  
287  /** Log severity levels that can be selected by the user. */
288  static constexpr std::array<BCLog::Level, 3> LogLevelsList()
289  {
290      return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
291  }
292  
293  std::string BCLog::Logger::LogLevelsString() const
294  {
295      const auto& levels = LogLevelsList();
296      return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
297  }
298  
299  std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const
300  {
301      std::string strStamped;
302  
303      if (!m_log_timestamps)
304          return strStamped;
305  
306      const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
307      strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
308      if (m_log_time_micros && !strStamped.empty()) {
309          strStamped.pop_back();
310          strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
311      }
312      if (mocktime > 0s) {
313          strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
314      }
315      strStamped += ' ';
316  
317      return strStamped;
318  }
319  
320  namespace BCLog {
321      /** Belts and suspenders: make sure outgoing log messages don't contain
322       * potentially suspicious characters, such as terminal control codes.
323       *
324       * This escapes control characters except newline ('\n') in C syntax.
325       * It escapes instead of removes them to still allow for troubleshooting
326       * issues where they accidentally end up in strings.
327       */
328      std::string LogEscapeMessage(std::string_view str) {
329          std::string ret;
330          for (char ch_in : str) {
331              uint8_t ch = (uint8_t)ch_in;
332              if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
333                  ret += ch_in;
334              } else {
335                  ret += strprintf("\\x%02x", ch);
336              }
337          }
338          return ret;
339      }
340  } // namespace BCLog
341  
342  std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
343  {
344      if (category == LogFlags::NONE) category = LogFlags::ALL;
345  
346      const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
347  
348      // If there is no category, Info is implied
349      if (!has_category && level == Level::Info) return {};
350  
351      std::string s{"["};
352      if (has_category) {
353          s += LogCategoryToStr(category);
354      }
355  
356      if (m_always_print_category_level || !has_category || level != Level::Debug) {
357          // If there is a category, Debug is implied, so don't add the level
358  
359          // Only add separator if we have a category
360          if (has_category) s += ":";
361          s += Logger::LogLevelToStr(level);
362      }
363  
364      s += "] ";
365      return s;
366  }
367  
368  static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
369  {
370      return memusage::DynamicUsage(buflog.str) +
371             memusage::DynamicUsage(buflog.threadname) +
372             memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
373  }
374  
375  BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
376      : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
377  
378  std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
379      SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
380  {
381      auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
382      std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
383      auto reset = [weak_limiter] {
384          if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
385      };
386      scheduler_func(reset, limiter->m_reset_window);
387      return limiter;
388  }
389  
390  BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
391      const std::source_location& source_loc,
392      const std::string& str)
393  {
394      StdLockGuard scoped_lock(m_mutex);
395      auto& stats{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second};
396      Status status{stats.m_dropped_bytes > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED};
397  
398      if (!stats.Consume(str.size()) && status == Status::UNSUPPRESSED) {
399          status = Status::NEWLY_SUPPRESSED;
400          m_suppression_active = true;
401      }
402  
403      return status;
404  }
405  
406  void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, const std::source_location& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const
407  {
408      if (!str.ends_with('\n')) str.push_back('\n');
409  
410      str.insert(0, GetLogPrefix(category, level));
411  
412      if (m_log_sourcelocations) {
413          str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name()));
414      }
415  
416      if (m_log_threadnames) {
417          str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname)));
418      }
419  
420      str.insert(0, LogTimestampStr(now, mocktime));
421  }
422  
423  void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
424  {
425      StdLockGuard scoped_lock(m_cs);
426      return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit);
427  }
428  
429  // NOLINTNEXTLINE(misc-no-recursion)
430  void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
431  {
432      std::string str_prefixed = LogEscapeMessage(str);
433  
434      if (m_buffering) {
435          {
436              BufferedLog buf{
437                  .now = SystemClock::now(),
438                  .mocktime = GetMockTime(),
439                  .str = str_prefixed,
440                  .threadname = util::ThreadGetInternalName(),
441                  .source_loc = std::move(source_loc),
442                  .category = category,
443                  .level = level,
444              };
445              m_cur_buffer_memusage += MemUsage(buf);
446              m_msgs_before_open.push_back(std::move(buf));
447          }
448  
449          while (m_cur_buffer_memusage > m_max_buffer_memusage) {
450              if (m_msgs_before_open.empty()) {
451                  m_cur_buffer_memusage = 0;
452                  break;
453              }
454              m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
455              m_msgs_before_open.pop_front();
456              ++m_buffer_lines_discarded;
457          }
458  
459          return;
460      }
461  
462      FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
463      bool ratelimit{false};
464      if (should_ratelimit && m_limiter) {
465          auto status{m_limiter->Consume(source_loc, str_prefixed)};
466          if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
467              // NOLINTNEXTLINE(misc-no-recursion)
468              LogPrintStr_(strprintf(
469                               "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
470                               "the last time window of %is. Suppressing logging to disk from this "
471                               "source location until time window resets. Console logging "
472                               "unaffected. Last log entry.",
473                               source_loc.file_name(), source_loc.line(), source_loc.function_name(),
474                               m_limiter->m_max_bytes,
475                               Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
476                           std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion
477          } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
478              ratelimit = true;
479          }
480      }
481  
482      // To avoid confusion caused by dropped log messages when debugging an issue,
483      // we prefix log lines with "[*]" when there are any suppressed source locations.
484      if (m_limiter && m_limiter->SuppressionsActive()) {
485          str_prefixed.insert(0, "[*] ");
486      }
487  
488      if (m_print_to_console) {
489          // print to console
490          fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
491          fflush(stdout);
492      }
493      for (const auto& cb : m_print_callbacks) {
494          cb(str_prefixed);
495      }
496      if (m_print_to_file && !ratelimit) {
497          assert(m_fileout != nullptr);
498  
499          // reopen the log file, if requested
500          if (m_reopen_file) {
501              m_reopen_file = false;
502              FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
503              if (new_fileout) {
504                  setbuf(new_fileout, nullptr); // unbuffered
505                  fclose(m_fileout);
506                  m_fileout = new_fileout;
507              }
508          }
509          FileWriteStr(str_prefixed, m_fileout);
510      }
511  }
512  
513  void BCLog::Logger::ShrinkDebugFile()
514  {
515      // Amount of debug.log to save at end when shrinking (must fit in memory)
516      constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
517  
518      assert(!m_file_path.empty());
519  
520      // Scroll debug.log if it's getting too big
521      FILE* file = fsbridge::fopen(m_file_path, "r");
522  
523      // Special files (e.g. device nodes) may not have a size.
524      size_t log_size = 0;
525      try {
526          log_size = fs::file_size(m_file_path);
527      } catch (const fs::filesystem_error&) {}
528  
529      // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
530      // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
531      if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
532      {
533          // Restart the file with some of the end
534          std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
535          if (fseek(file, -((long)vch.size()), SEEK_END)) {
536              LogWarning("Failed to shrink debug log file: fseek(...) failed");
537              fclose(file);
538              return;
539          }
540          int nBytes = fread(vch.data(), 1, vch.size(), file);
541          fclose(file);
542  
543          file = fsbridge::fopen(m_file_path, "w");
544          if (file)
545          {
546              fwrite(vch.data(), 1, nBytes, file);
547              fclose(file);
548          }
549      }
550      else if (file != nullptr)
551          fclose(file);
552  }
553  
554  void BCLog::LogRateLimiter::Reset()
555  {
556      decltype(m_source_locations) source_locations;
557      {
558          StdLockGuard scoped_lock(m_mutex);
559          source_locations.swap(m_source_locations);
560          m_suppression_active = false;
561      }
562      for (const auto& [source_loc, stats] : source_locations) {
563          if (stats.m_dropped_bytes == 0) continue;
564          LogPrintLevel_(
565              LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false,
566              "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.",
567              source_loc.file_name(), source_loc.line(), source_loc.function_name(),
568              stats.m_dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
569      }
570  }
571  
572  bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes)
573  {
574      if (bytes > m_available_bytes) {
575          m_dropped_bytes += bytes;
576          m_available_bytes = 0;
577          return false;
578      }
579  
580      m_available_bytes -= bytes;
581      return true;
582  }
583  
584  bool BCLog::Logger::SetLogLevel(std::string_view level_str)
585  {
586      const auto level = GetLogLevel(level_str);
587      if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
588      m_log_level = level.value();
589      return true;
590  }
591  
592  bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str)
593  {
594      BCLog::LogFlags flag;
595      if (!GetLogCategory(flag, category_str)) return false;
596  
597      const auto level = GetLogLevel(level_str);
598      if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
599  
600      StdLockGuard scoped_lock(m_cs);
601      m_category_log_levels[flag] = level.value();
602      return true;
603  }