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