1  // Copyright (c) 2009-2010 Satoshi Nakamoto
  2  // Copyright (c) 2009-2022 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 <util/fs.h>
  8  #include <util/string.h>
  9  #include <util/threadnames.h>
 10  #include <util/time.h>
 11  
 12  #include <algorithm>
 13  #include <array>
 14  #include <mutex>
 15  #include <optional>
 16  
 17  const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
 18  constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
 19  
 20  BCLog::Logger& LogInstance()
 21  {
 22  /**
 23   * NOTE: the logger instances is leaked on exit. This is ugly, but will be
 24   * cleaned up by the OS/libc. Defining a logger as a global object doesn't work
 25   * since the order of destruction of static/global objects is undefined.
 26   * Consider if the logger gets destroyed, and then some later destructor calls
 27   * LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to
 28   * access the logger. When the shutdown sequence is fully audited and tested,
 29   * explicit destruction of these objects can be implemented by changing this
 30   * from a raw pointer to a std::unique_ptr.
 31   * Since the ~Logger() destructor is never called, the Logger class and all
 32   * its subclasses must have implicitly-defined destructors.
 33   *
 34   * This method of initialization was originally introduced in
 35   * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
 36   */
 37      static BCLog::Logger* g_logger{new BCLog::Logger()};
 38      return *g_logger;
 39  }
 40  
 41  bool fLogIPs = DEFAULT_LOGIPS;
 42  
 43  static int FileWriteStr(const std::string &str, FILE *fp)
 44  {
 45      return fwrite(str.data(), 1, str.size(), fp);
 46  }
 47  
 48  bool BCLog::Logger::StartLogging()
 49  {
 50      StdLockGuard scoped_lock(m_cs);
 51  
 52      assert(m_buffering);
 53      assert(m_fileout == nullptr);
 54  
 55      if (m_print_to_file) {
 56          assert(!m_file_path.empty());
 57          m_fileout = fsbridge::fopen(m_file_path, "a");
 58          if (!m_fileout) {
 59              return false;
 60          }
 61  
 62          setbuf(m_fileout, nullptr); // unbuffered
 63  
 64          // Add newlines to the logfile to distinguish this execution from the
 65          // last one.
 66          FileWriteStr("\n\n\n\n\n", m_fileout);
 67      }
 68  
 69      // dump buffered messages from before we opened the log
 70      m_buffering = false;
 71      while (!m_msgs_before_open.empty()) {
 72          const std::string& s = m_msgs_before_open.front();
 73  
 74          if (m_print_to_file) FileWriteStr(s, m_fileout);
 75          if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
 76          for (const auto& cb : m_print_callbacks) {
 77              cb(s);
 78          }
 79  
 80          m_msgs_before_open.pop_front();
 81      }
 82      if (m_print_to_console) fflush(stdout);
 83  
 84      return true;
 85  }
 86  
 87  void BCLog::Logger::DisconnectTestLogger()
 88  {
 89      StdLockGuard scoped_lock(m_cs);
 90      m_buffering = true;
 91      if (m_fileout != nullptr) fclose(m_fileout);
 92      m_fileout = nullptr;
 93      m_print_callbacks.clear();
 94  }
 95  
 96  void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
 97  {
 98      m_categories |= flag;
 99  }
100  
101  bool BCLog::Logger::EnableCategory(const std::string& str)
102  {
103      BCLog::LogFlags flag;
104      if (!GetLogCategory(flag, str)) return false;
105      EnableCategory(flag);
106      return true;
107  }
108  
109  void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
110  {
111      m_categories &= ~flag;
112  }
113  
114  bool BCLog::Logger::DisableCategory(const std::string& str)
115  {
116      BCLog::LogFlags flag;
117      if (!GetLogCategory(flag, str)) return false;
118      DisableCategory(flag);
119      return true;
120  }
121  
122  bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
123  {
124      return (m_categories.load(std::memory_order_relaxed) & category) != 0;
125  }
126  
127  bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
128  {
129      // Log messages at Info, Warning and Error level unconditionally, so that
130      // important troubleshooting information doesn't get lost.
131      if (level >= BCLog::Level::Info) return true;
132  
133      if (!WillLogCategory(category)) return false;
134  
135      StdLockGuard scoped_lock(m_cs);
136      const auto it{m_category_log_levels.find(category)};
137      return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
138  }
139  
140  bool BCLog::Logger::DefaultShrinkDebugFile() const
141  {
142      return m_categories == BCLog::NONE;
143  }
144  
145  struct CLogCategoryDesc {
146      BCLog::LogFlags flag;
147      std::string category;
148  };
149  
150  const CLogCategoryDesc LogCategories[] =
151  {
152      {BCLog::NONE, "0"},
153      {BCLog::NONE, ""},
154      {BCLog::NET, "net"},
155      {BCLog::TOR, "tor"},
156      {BCLog::MEMPOOL, "mempool"},
157      {BCLog::HTTP, "http"},
158      {BCLog::BENCH, "bench"},
159      {BCLog::ZMQ, "zmq"},
160      {BCLog::WALLETDB, "walletdb"},
161      {BCLog::RPC, "rpc"},
162      {BCLog::ESTIMATEFEE, "estimatefee"},
163      {BCLog::ADDRMAN, "addrman"},
164      {BCLog::SELECTCOINS, "selectcoins"},
165      {BCLog::REINDEX, "reindex"},
166      {BCLog::CMPCTBLOCK, "cmpctblock"},
167      {BCLog::RAND, "rand"},
168      {BCLog::PRUNE, "prune"},
169      {BCLog::PROXY, "proxy"},
170      {BCLog::MEMPOOLREJ, "mempoolrej"},
171      {BCLog::LIBEVENT, "libevent"},
172      {BCLog::COINDB, "coindb"},
173      {BCLog::QT, "qt"},
174      {BCLog::LEVELDB, "leveldb"},
175      {BCLog::VALIDATION, "validation"},
176      {BCLog::I2P, "i2p"},
177      {BCLog::IPC, "ipc"},
178  #ifdef DEBUG_LOCKCONTENTION
179      {BCLog::LOCK, "lock"},
180  #endif
181      {BCLog::UTIL, "util"},
182      {BCLog::BLOCKSTORAGE, "blockstorage"},
183      {BCLog::TXRECONCILIATION, "txreconciliation"},
184      {BCLog::SCAN, "scan"},
185      {BCLog::TXPACKAGES, "txpackages"},
186      {BCLog::ALL, "1"},
187      {BCLog::ALL, "all"},
188  };
189  
190  bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
191  {
192      if (str.empty()) {
193          flag = BCLog::ALL;
194          return true;
195      }
196      for (const CLogCategoryDesc& category_desc : LogCategories) {
197          if (category_desc.category == str) {
198              flag = category_desc.flag;
199              return true;
200          }
201      }
202      return false;
203  }
204  
205  std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
206  {
207      switch (level) {
208      case BCLog::Level::Trace:
209          return "trace";
210      case BCLog::Level::Debug:
211          return "debug";
212      case BCLog::Level::Info:
213          return "info";
214      case BCLog::Level::Warning:
215          return "warning";
216      case BCLog::Level::Error:
217          return "error";
218      }
219      assert(false);
220  }
221  
222  std::string LogCategoryToStr(BCLog::LogFlags category)
223  {
224      // Each log category string representation should sync with LogCategories
225      switch (category) {
226      case BCLog::LogFlags::NONE:
227          return "";
228      case BCLog::LogFlags::NET:
229          return "net";
230      case BCLog::LogFlags::TOR:
231          return "tor";
232      case BCLog::LogFlags::MEMPOOL:
233          return "mempool";
234      case BCLog::LogFlags::HTTP:
235          return "http";
236      case BCLog::LogFlags::BENCH:
237          return "bench";
238      case BCLog::LogFlags::ZMQ:
239          return "zmq";
240      case BCLog::LogFlags::WALLETDB:
241          return "walletdb";
242      case BCLog::LogFlags::RPC:
243          return "rpc";
244      case BCLog::LogFlags::ESTIMATEFEE:
245          return "estimatefee";
246      case BCLog::LogFlags::ADDRMAN:
247          return "addrman";
248      case BCLog::LogFlags::SELECTCOINS:
249          return "selectcoins";
250      case BCLog::LogFlags::REINDEX:
251          return "reindex";
252      case BCLog::LogFlags::CMPCTBLOCK:
253          return "cmpctblock";
254      case BCLog::LogFlags::RAND:
255          return "rand";
256      case BCLog::LogFlags::PRUNE:
257          return "prune";
258      case BCLog::LogFlags::PROXY:
259          return "proxy";
260      case BCLog::LogFlags::MEMPOOLREJ:
261          return "mempoolrej";
262      case BCLog::LogFlags::LIBEVENT:
263          return "libevent";
264      case BCLog::LogFlags::COINDB:
265          return "coindb";
266      case BCLog::LogFlags::QT:
267          return "qt";
268      case BCLog::LogFlags::LEVELDB:
269          return "leveldb";
270      case BCLog::LogFlags::VALIDATION:
271          return "validation";
272      case BCLog::LogFlags::I2P:
273          return "i2p";
274      case BCLog::LogFlags::IPC:
275          return "ipc";
276  #ifdef DEBUG_LOCKCONTENTION
277      case BCLog::LogFlags::LOCK:
278          return "lock";
279  #endif
280      case BCLog::LogFlags::UTIL:
281          return "util";
282      case BCLog::LogFlags::BLOCKSTORAGE:
283          return "blockstorage";
284      case BCLog::LogFlags::TXRECONCILIATION:
285          return "txreconciliation";
286      case BCLog::LogFlags::SCAN:
287          return "scan";
288      case BCLog::LogFlags::TXPACKAGES:
289          return "txpackages";
290      case BCLog::LogFlags::ALL:
291          return "all";
292      }
293      assert(false);
294  }
295  
296  static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
297  {
298      if (level_str == "trace") {
299          return BCLog::Level::Trace;
300      } else if (level_str == "debug") {
301          return BCLog::Level::Debug;
302      } else if (level_str == "info") {
303          return BCLog::Level::Info;
304      } else if (level_str == "warning") {
305          return BCLog::Level::Warning;
306      } else if (level_str == "error") {
307          return BCLog::Level::Error;
308      } else {
309          return std::nullopt;
310      }
311  }
312  
313  std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
314  {
315      // Sort log categories by alphabetical order.
316      std::array<CLogCategoryDesc, std::size(LogCategories)> categories;
317      std::copy(std::begin(LogCategories), std::end(LogCategories), categories.begin());
318      std::sort(categories.begin(), categories.end(), [](auto a, auto b) { return a.category < b.category; });
319  
320      std::vector<LogCategory> ret;
321      for (const CLogCategoryDesc& category_desc : categories) {
322          if (category_desc.flag == BCLog::NONE || category_desc.flag == BCLog::ALL) continue;
323          LogCategory catActive;
324          catActive.category = category_desc.category;
325          catActive.active = WillLogCategory(category_desc.flag);
326          ret.push_back(catActive);
327      }
328      return ret;
329  }
330  
331  /** Log severity levels that can be selected by the user. */
332  static constexpr std::array<BCLog::Level, 3> LogLevelsList()
333  {
334      return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
335  }
336  
337  std::string BCLog::Logger::LogLevelsString() const
338  {
339      const auto& levels = LogLevelsList();
340      return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
341  }
342  
343  std::string BCLog::Logger::LogTimestampStr(const std::string& str)
344  {
345      std::string strStamped;
346  
347      if (!m_log_timestamps)
348          return str;
349  
350      if (m_started_new_line) {
351          const auto now{SystemClock::now()};
352          const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
353          strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
354          if (m_log_time_micros && !strStamped.empty()) {
355              strStamped.pop_back();
356              strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
357          }
358          std::chrono::seconds mocktime = GetMockTime();
359          if (mocktime > 0s) {
360              strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
361          }
362          strStamped += ' ' + str;
363      } else
364          strStamped = str;
365  
366      return strStamped;
367  }
368  
369  namespace BCLog {
370      /** Belts and suspenders: make sure outgoing log messages don't contain
371       * potentially suspicious characters, such as terminal control codes.
372       *
373       * This escapes control characters except newline ('\n') in C syntax.
374       * It escapes instead of removes them to still allow for troubleshooting
375       * issues where they accidentally end up in strings.
376       */
377      std::string LogEscapeMessage(const std::string& str) {
378          std::string ret;
379          for (char ch_in : str) {
380              uint8_t ch = (uint8_t)ch_in;
381              if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
382                  ret += ch_in;
383              } else {
384                  ret += strprintf("\\x%02x", ch);
385              }
386          }
387          return ret;
388      }
389  } // namespace BCLog
390  
391  std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
392  {
393      if (category == LogFlags::NONE) category = LogFlags::ALL;
394  
395      const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
396  
397      // If there is no category, Info is implied
398      if (!has_category && level == Level::Info) return {};
399  
400      std::string s{"["};
401      if (has_category) {
402          s += LogCategoryToStr(category);
403      }
404  
405      if (m_always_print_category_level || !has_category || level != Level::Debug) {
406          // If there is a category, Debug is implied, so don't add the level
407  
408          // Only add separator if we have a category
409          if (has_category) s += ":";
410          s += Logger::LogLevelToStr(level);
411      }
412  
413      s += "] ";
414      return s;
415  }
416  
417  void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
418  {
419      StdLockGuard scoped_lock(m_cs);
420      std::string str_prefixed = LogEscapeMessage(str);
421  
422      if (m_started_new_line) {
423          str_prefixed.insert(0, GetLogPrefix(category, level));
424      }
425  
426      if (m_log_sourcelocations && m_started_new_line) {
427          str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
428      }
429  
430      if (m_log_threadnames && m_started_new_line) {
431          const auto& threadname = util::ThreadGetInternalName();
432          str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
433      }
434  
435      str_prefixed = LogTimestampStr(str_prefixed);
436  
437      m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
438  
439      if (m_buffering) {
440          // buffer if we haven't started logging yet
441          m_msgs_before_open.push_back(str_prefixed);
442          return;
443      }
444  
445      if (m_print_to_console) {
446          // print to console
447          fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
448          fflush(stdout);
449      }
450      for (const auto& cb : m_print_callbacks) {
451          cb(str_prefixed);
452      }
453      if (m_print_to_file) {
454          assert(m_fileout != nullptr);
455  
456          // reopen the log file, if requested
457          if (m_reopen_file) {
458              m_reopen_file = false;
459              FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
460              if (new_fileout) {
461                  setbuf(new_fileout, nullptr); // unbuffered
462                  fclose(m_fileout);
463                  m_fileout = new_fileout;
464              }
465          }
466          FileWriteStr(str_prefixed, m_fileout);
467      }
468  }
469  
470  void BCLog::Logger::ShrinkDebugFile()
471  {
472      // Amount of debug.log to save at end when shrinking (must fit in memory)
473      constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
474  
475      assert(!m_file_path.empty());
476  
477      // Scroll debug.log if it's getting too big
478      FILE* file = fsbridge::fopen(m_file_path, "r");
479  
480      // Special files (e.g. device nodes) may not have a size.
481      size_t log_size = 0;
482      try {
483          log_size = fs::file_size(m_file_path);
484      } catch (const fs::filesystem_error&) {}
485  
486      // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
487      // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
488      if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
489      {
490          // Restart the file with some of the end
491          std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
492          if (fseek(file, -((long)vch.size()), SEEK_END)) {
493              LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
494              fclose(file);
495              return;
496          }
497          int nBytes = fread(vch.data(), 1, vch.size(), file);
498          fclose(file);
499  
500          file = fsbridge::fopen(m_file_path, "w");
501          if (file)
502          {
503              fwrite(vch.data(), 1, nBytes, file);
504              fclose(file);
505          }
506      }
507      else if (file != nullptr)
508          fclose(file);
509  }
510  
511  bool BCLog::Logger::SetLogLevel(const std::string& level_str)
512  {
513      const auto level = GetLogLevel(level_str);
514      if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
515      m_log_level = level.value();
516      return true;
517  }
518  
519  bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str)
520  {
521      BCLog::LogFlags flag;
522      if (!GetLogCategory(flag, category_str)) return false;
523  
524      const auto level = GetLogLevel(level_str);
525      if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
526  
527      StdLockGuard scoped_lock(m_cs);
528      m_category_log_levels[flag] = level.value();
529      return true;
530  }