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