Bitcoin Core  27.99.0
P2P Digital Currency
logging.cpp
Go to the documentation of this file.
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";
19 
21 {
37  static BCLog::Logger* g_logger{new BCLog::Logger()};
38  return *g_logger;
39 }
40 
42 
43 static int FileWriteStr(const std::string &str, FILE *fp)
44 {
45  return fwrite(str.data(), 1, str.size(), fp);
46 }
47 
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 
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 
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 
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 
123 {
124  return (m_categories.load(std::memory_order_relaxed) & category) != 0;
125 }
126 
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 
141 {
142  return m_categories == BCLog::NONE;
143 }
144 
147  std::string category;
148 };
149 
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 
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";
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) {
227  return "";
229  return "net";
231  return "tor";
233  return "mempool";
235  return "http";
237  return "bench";
238  case BCLog::LogFlags::ZMQ:
239  return "zmq";
241  return "walletdb";
242  case BCLog::LogFlags::RPC:
243  return "rpc";
245  return "estimatefee";
247  return "addrman";
249  return "selectcoins";
251  return "reindex";
253  return "cmpctblock";
255  return "rand";
257  return "prune";
259  return "proxy";
261  return "mempoolrej";
263  return "libevent";
265  return "coindb";
266  case BCLog::LogFlags::QT:
267  return "qt";
269  return "leveldb";
271  return "validation";
273  return "i2p";
275  return "ipc";
276 #ifdef DEBUG_LOCKCONTENTION
278  return "lock";
279 #endif
281  return "util";
283  return "blockstorage";
285  return "txreconciliation";
287  return "scan";
289  return "txpackages";
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 
332 static constexpr std::array<BCLog::Level, 3> LogLevelsList()
333 {
335 }
336 
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 {
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 
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 }
int ret
static std::string LogLevelToStr(BCLog::Level level)
Returns the string representation of a log level.
Definition: logging.cpp:205
bool WillLogCategory(LogFlags category) const
Definition: logging.cpp:122
std::string LogTimestampStr(const std::string &str)
Definition: logging.cpp:343
void DisconnectTestLogger()
Only for testing.
Definition: logging.cpp:87
bool DefaultShrinkDebugFile() const
Definition: logging.cpp:140
void SetLogLevel(Level level)
Definition: logging.h:175
bool WillLogCategoryLevel(LogFlags category, Level level) const
Definition: logging.cpp:127
fs::path m_file_path
Definition: logging.h:125
void LogPrintStr(const std::string &str, const std::string &logging_function, const std::string &source_file, int source_line, BCLog::LogFlags category, BCLog::Level level)
Send a string to the log output.
Definition: logging.cpp:417
std::vector< LogCategory > LogCategoriesList() const
Returns a vector of the log categories in alphabetical order.
Definition: logging.cpp:313
void EnableCategory(LogFlags flag)
Definition: logging.cpp:96
bool StartLogging()
Start logging (and flush all buffered messages)
Definition: logging.cpp:48
std::string GetLogPrefix(LogFlags category, Level level) const
Definition: logging.cpp:391
std::string LogLevelsString() const
Returns a string with all user-selectable log levels.
Definition: logging.cpp:337
void ShrinkDebugFile()
Definition: logging.cpp:470
bool m_print_to_file
Definition: logging.h:117
void SetCategoryLogLevel(const std::unordered_map< LogFlags, Level > &levels)
Definition: logging.h:167
bool m_print_to_console
Definition: logging.h:116
StdMutex m_cs
Definition: logging.h:87
void DisableCategory(LogFlags flag)
Definition: logging.cpp:109
const CLogCategoryDesc LogCategories[]
Definition: logging.cpp:150
static constexpr std::array< BCLog::Level, 3 > LogLevelsList()
Log severity levels that can be selected by the user.
Definition: logging.cpp:332
std::string LogCategoryToStr(BCLog::LogFlags category)
Definition: logging.cpp:222
static int FileWriteStr(const std::string &str, FILE *fp)
Definition: logging.cpp:43
bool GetLogCategory(BCLog::LogFlags &flag, const std::string &str)
Return true if str parses as a log category and set the flag.
Definition: logging.cpp:190
bool fLogIPs
Definition: logging.cpp:41
const char *const DEFAULT_DEBUGLOGFILE
Definition: logging.cpp:17
static std::optional< BCLog::Level > GetLogLevel(const std::string &level_str)
Definition: logging.cpp:296
constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL
Definition: logging.cpp:18
BCLog::Logger & LogInstance()
Definition: logging.cpp:20
static const bool DEFAULT_LOGIPS
Definition: logging.h:24
#define LogPrintf(...)
Definition: logging.h:245
Definition: timer.h:19
Level
Definition: logging.h:75
std::string LogEscapeMessage(const std::string &str)
Belts and suspenders: make sure outgoing log messages don't contain potentially suspicious characters...
Definition: logging.cpp:377
LogFlags
Definition: logging.h:39
@ ESTIMATEFEE
Definition: logging.h:49
@ TXRECONCILIATION
Definition: logging.h:70
@ RAND
Definition: logging.h:54
@ BLOCKSTORAGE
Definition: logging.h:69
@ COINDB
Definition: logging.h:59
@ REINDEX
Definition: logging.h:52
@ TXPACKAGES
Definition: logging.h:72
@ WALLETDB
Definition: logging.h:47
@ SCAN
Definition: logging.h:71
@ ADDRMAN
Definition: logging.h:50
@ ALL
Definition: logging.h:73
@ RPC
Definition: logging.h:48
@ HTTP
Definition: logging.h:44
@ LEVELDB
Definition: logging.h:61
@ NONE
Definition: logging.h:40
@ VALIDATION
Definition: logging.h:62
@ MEMPOOLREJ
Definition: logging.h:57
@ PRUNE
Definition: logging.h:55
@ TOR
Definition: logging.h:42
@ LIBEVENT
Definition: logging.h:58
@ CMPCTBLOCK
Definition: logging.h:53
@ PROXY
Definition: logging.h:56
@ ZMQ
Definition: logging.h:46
@ IPC
Definition: logging.h:64
@ MEMPOOL
Definition: logging.h:43
@ SELECTCOINS
Definition: logging.h:51
@ I2P
Definition: logging.h:63
@ BENCH
Definition: logging.h:45
@ NET
Definition: logging.h:41
@ UTIL
Definition: logging.h:68
@ QT
Definition: logging.h:60
FILE * fopen(const fs::path &p, const char *mode)
Definition: fs.cpp:26
const std::string & ThreadGetInternalName()
Get the thread's internal (in-memory) name; used e.g.
Definition: threadnames.cpp:55
std::string RemovePrefix(std::string_view str, std::string_view prefix)
Definition: string.h:54
std::string ToString(const T &t)
Locale-independent version of std::to_string.
Definition: string.h:109
auto Join(const C &container, const S &separator, UnaryOp unary_op)
Join all container items.
Definition: string.h:68
BCLog::LogFlags flag
Definition: logging.cpp:146
std::string category
Definition: logging.cpp:147
bool active
Definition: logging.h:35
std::string category
Definition: logging.h:34
#define LOCK(cs)
Definition: sync.h:257
std::chrono::seconds GetMockTime()
For testing.
Definition: time.cpp:92
std::string FormatISO8601DateTime(int64_t nTime)
ISO 8601 formatting is preferred.
Definition: time.cpp:99
constexpr int64_t count_seconds(std::chrono::seconds t)
Definition: time.h:54
#define strprintf
Format arguments and return the string or write to given std::ostream (see tinyformat::format doc for...
Definition: tinyformat.h:1162
assert(!tx.IsCoinBase())