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 <array>
13 #include <map>
14 #include <optional>
15 
16 using util::Join;
17 using util::RemovePrefix;
18 using util::ToString;
19 
20 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
22 
24 {
40  static BCLog::Logger* g_logger{new BCLog::Logger()};
41  return *g_logger;
42 }
43 
45 
46 static int FileWriteStr(const std::string &str, FILE *fp)
47 {
48  return fwrite(str.data(), 1, str.size(), fp);
49 }
50 
52 {
53  StdLockGuard scoped_lock(m_cs);
54 
55  assert(m_buffering);
56  assert(m_fileout == nullptr);
57 
58  if (m_print_to_file) {
59  assert(!m_file_path.empty());
60  m_fileout = fsbridge::fopen(m_file_path, "a");
61  if (!m_fileout) {
62  return false;
63  }
64 
65  setbuf(m_fileout, nullptr); // unbuffered
66 
67  // Add newlines to the logfile to distinguish this execution from the
68  // last one.
69  FileWriteStr("\n\n\n\n\n", m_fileout);
70  }
71 
72  // dump buffered messages from before we opened the log
73  m_buffering = false;
74  while (!m_msgs_before_open.empty()) {
75  const std::string& s = m_msgs_before_open.front();
76 
77  if (m_print_to_file) FileWriteStr(s, m_fileout);
78  if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
79  for (const auto& cb : m_print_callbacks) {
80  cb(s);
81  }
82 
83  m_msgs_before_open.pop_front();
84  }
85  if (m_print_to_console) fflush(stdout);
86 
87  return true;
88 }
89 
91 {
92  StdLockGuard scoped_lock(m_cs);
93  m_buffering = true;
94  if (m_fileout != nullptr) fclose(m_fileout);
95  m_fileout = nullptr;
96  m_print_callbacks.clear();
97 }
98 
100 {
101  m_categories |= flag;
102 }
103 
104 bool BCLog::Logger::EnableCategory(const std::string& str)
105 {
106  BCLog::LogFlags flag;
107  if (!GetLogCategory(flag, str)) return false;
108  EnableCategory(flag);
109  return true;
110 }
111 
113 {
114  m_categories &= ~flag;
115 }
116 
117 bool BCLog::Logger::DisableCategory(const std::string& str)
118 {
119  BCLog::LogFlags flag;
120  if (!GetLogCategory(flag, str)) return false;
121  DisableCategory(flag);
122  return true;
123 }
124 
126 {
127  return (m_categories.load(std::memory_order_relaxed) & category) != 0;
128 }
129 
131 {
132  // Log messages at Info, Warning and Error level unconditionally, so that
133  // important troubleshooting information doesn't get lost.
134  if (level >= BCLog::Level::Info) return true;
135 
136  if (!WillLogCategory(category)) return false;
137 
138  StdLockGuard scoped_lock(m_cs);
139  const auto it{m_category_log_levels.find(category)};
140  return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
141 }
142 
144 {
145  return m_categories == BCLog::NONE;
146 }
147 
148 static const std::map<std::string, BCLog::LogFlags> LOG_CATEGORIES_BY_STR{
149  {"0", BCLog::NONE},
150  {"", BCLog::NONE},
151  {"net", BCLog::NET},
152  {"tor", BCLog::TOR},
153  {"mempool", BCLog::MEMPOOL},
154  {"http", BCLog::HTTP},
155  {"bench", BCLog::BENCH},
156  {"zmq", BCLog::ZMQ},
157  {"walletdb", BCLog::WALLETDB},
158  {"rpc", BCLog::RPC},
159  {"estimatefee", BCLog::ESTIMATEFEE},
160  {"addrman", BCLog::ADDRMAN},
161  {"selectcoins", BCLog::SELECTCOINS},
162  {"reindex", BCLog::REINDEX},
163  {"cmpctblock", BCLog::CMPCTBLOCK},
164  {"rand", BCLog::RAND},
165  {"prune", BCLog::PRUNE},
166  {"proxy", BCLog::PROXY},
167  {"mempoolrej", BCLog::MEMPOOLREJ},
168  {"libevent", BCLog::LIBEVENT},
169  {"coindb", BCLog::COINDB},
170  {"qt", BCLog::QT},
171  {"leveldb", BCLog::LEVELDB},
172  {"validation", BCLog::VALIDATION},
173  {"i2p", BCLog::I2P},
174  {"ipc", BCLog::IPC},
175 #ifdef DEBUG_LOCKCONTENTION
176  {"lock", BCLog::LOCK},
177 #endif
178  {"blockstorage", BCLog::BLOCKSTORAGE},
179  {"txreconciliation", BCLog::TXRECONCILIATION},
180  {"scan", BCLog::SCAN},
181  {"txpackages", BCLog::TXPACKAGES},
182  {"1", BCLog::ALL},
183  {"all", BCLog::ALL},
184 };
185 
186 static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
187  // Swap keys and values from LOG_CATEGORIES_BY_STR.
188  [](const std::map<std::string, BCLog::LogFlags>& in) {
189  std::unordered_map<BCLog::LogFlags, std::string> out;
190  for (const auto& [k, v] : in) {
191  switch (v) {
192  case BCLog::NONE: out.emplace(BCLog::NONE, ""); break;
193  case BCLog::ALL: out.emplace(BCLog::ALL, "all"); break;
194  default: out.emplace(v, k);
195  }
196  }
197  return out;
199 };
200 
201 bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
202 {
203  if (str.empty()) {
204  flag = BCLog::ALL;
205  return true;
206  }
207  auto it = LOG_CATEGORIES_BY_STR.find(str);
208  if (it != LOG_CATEGORIES_BY_STR.end()) {
209  flag = it->second;
210  return true;
211  }
212  return false;
213 }
214 
216 {
217  switch (level) {
218  case BCLog::Level::Trace:
219  return "trace";
220  case BCLog::Level::Debug:
221  return "debug";
222  case BCLog::Level::Info:
223  return "info";
225  return "warning";
226  case BCLog::Level::Error:
227  return "error";
228  }
229  assert(false);
230 }
231 
232 std::string LogCategoryToStr(BCLog::LogFlags category)
233 {
234  auto it = LOG_CATEGORIES_BY_FLAG.find(category);
235  assert(it != LOG_CATEGORIES_BY_FLAG.end());
236  return it->second;
237 }
238 
239 static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
240 {
241  if (level_str == "trace") {
242  return BCLog::Level::Trace;
243  } else if (level_str == "debug") {
244  return BCLog::Level::Debug;
245  } else if (level_str == "info") {
246  return BCLog::Level::Info;
247  } else if (level_str == "warning") {
248  return BCLog::Level::Warning;
249  } else if (level_str == "error") {
250  return BCLog::Level::Error;
251  } else {
252  return std::nullopt;
253  }
254 }
255 
256 std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
257 {
258  std::vector<LogCategory> ret;
259  for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
260  if (flag != BCLog::NONE && flag != BCLog::ALL) {
261  ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
262  }
263  }
264  return ret;
265 }
266 
268 static constexpr std::array<BCLog::Level, 3> LogLevelsList()
269 {
271 }
272 
274 {
275  const auto& levels = LogLevelsList();
276  return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
277 }
278 
279 std::string BCLog::Logger::LogTimestampStr(const std::string& str)
280 {
281  std::string strStamped;
282 
283  if (!m_log_timestamps)
284  return str;
285 
286  if (m_started_new_line) {
287  const auto now{SystemClock::now()};
288  const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
289  strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
290  if (m_log_time_micros && !strStamped.empty()) {
291  strStamped.pop_back();
292  strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
293  }
294  std::chrono::seconds mocktime = GetMockTime();
295  if (mocktime > 0s) {
296  strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
297  }
298  strStamped += ' ' + str;
299  } else
300  strStamped = str;
301 
302  return strStamped;
303 }
304 
305 namespace BCLog {
313  std::string LogEscapeMessage(const std::string& str) {
314  std::string ret;
315  for (char ch_in : str) {
316  uint8_t ch = (uint8_t)ch_in;
317  if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
318  ret += ch_in;
319  } else {
320  ret += strprintf("\\x%02x", ch);
321  }
322  }
323  return ret;
324  }
325 } // namespace BCLog
326 
327 std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
328 {
329  if (category == LogFlags::NONE) category = LogFlags::ALL;
330 
331  const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
332 
333  // If there is no category, Info is implied
334  if (!has_category && level == Level::Info) return {};
335 
336  std::string s{"["};
337  if (has_category) {
338  s += LogCategoryToStr(category);
339  }
340 
341  if (m_always_print_category_level || !has_category || level != Level::Debug) {
342  // If there is a category, Debug is implied, so don't add the level
343 
344  // Only add separator if we have a category
345  if (has_category) s += ":";
346  s += Logger::LogLevelToStr(level);
347  }
348 
349  s += "] ";
350  return s;
351 }
352 
353 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)
354 {
355  StdLockGuard scoped_lock(m_cs);
356  std::string str_prefixed = LogEscapeMessage(str);
357 
358  if (m_started_new_line) {
359  str_prefixed.insert(0, GetLogPrefix(category, level));
360  }
361 
362  if (m_log_sourcelocations && m_started_new_line) {
363  str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
364  }
365 
366  if (m_log_threadnames && m_started_new_line) {
367  const auto& threadname = util::ThreadGetInternalName();
368  str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
369  }
370 
371  str_prefixed = LogTimestampStr(str_prefixed);
372 
373  m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
374 
375  if (m_buffering) {
376  // buffer if we haven't started logging yet
377  m_msgs_before_open.push_back(str_prefixed);
378  return;
379  }
380 
381  if (m_print_to_console) {
382  // print to console
383  fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
384  fflush(stdout);
385  }
386  for (const auto& cb : m_print_callbacks) {
387  cb(str_prefixed);
388  }
389  if (m_print_to_file) {
390  assert(m_fileout != nullptr);
391 
392  // reopen the log file, if requested
393  if (m_reopen_file) {
394  m_reopen_file = false;
395  FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
396  if (new_fileout) {
397  setbuf(new_fileout, nullptr); // unbuffered
398  fclose(m_fileout);
399  m_fileout = new_fileout;
400  }
401  }
402  FileWriteStr(str_prefixed, m_fileout);
403  }
404 }
405 
407 {
408  // Amount of debug.log to save at end when shrinking (must fit in memory)
409  constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
410 
411  assert(!m_file_path.empty());
412 
413  // Scroll debug.log if it's getting too big
414  FILE* file = fsbridge::fopen(m_file_path, "r");
415 
416  // Special files (e.g. device nodes) may not have a size.
417  size_t log_size = 0;
418  try {
419  log_size = fs::file_size(m_file_path);
420  } catch (const fs::filesystem_error&) {}
421 
422  // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
423  // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
424  if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
425  {
426  // Restart the file with some of the end
427  std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
428  if (fseek(file, -((long)vch.size()), SEEK_END)) {
429  LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
430  fclose(file);
431  return;
432  }
433  int nBytes = fread(vch.data(), 1, vch.size(), file);
434  fclose(file);
435 
436  file = fsbridge::fopen(m_file_path, "w");
437  if (file)
438  {
439  fwrite(vch.data(), 1, nBytes, file);
440  fclose(file);
441  }
442  }
443  else if (file != nullptr)
444  fclose(file);
445 }
446 
447 bool BCLog::Logger::SetLogLevel(const std::string& level_str)
448 {
449  const auto level = GetLogLevel(level_str);
450  if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
451  m_log_level = level.value();
452  return true;
453 }
454 
455 bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str)
456 {
457  BCLog::LogFlags flag;
458  if (!GetLogCategory(flag, category_str)) return false;
459 
460  const auto level = GetLogLevel(level_str);
461  if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
462 
463  StdLockGuard scoped_lock(m_cs);
464  m_category_log_levels[flag] = level.value();
465  return true;
466 }
int ret
static std::string LogLevelToStr(BCLog::Level level)
Returns the string representation of a log level.
Definition: logging.cpp:215
bool WillLogCategory(LogFlags category) const
Definition: logging.cpp:125
std::string LogTimestampStr(const std::string &str)
Definition: logging.cpp:279
void DisconnectTestLogger()
Only for testing.
Definition: logging.cpp:90
bool DefaultShrinkDebugFile() const
Definition: logging.cpp:143
void SetLogLevel(Level level)
Definition: logging.h:174
bool WillLogCategoryLevel(LogFlags category, Level level) const
Definition: logging.cpp:130
fs::path m_file_path
Definition: logging.h:124
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:353
std::vector< LogCategory > LogCategoriesList() const
Returns a vector of the log categories in alphabetical order.
Definition: logging.cpp:256
void EnableCategory(LogFlags flag)
Definition: logging.cpp:99
bool StartLogging()
Start logging (and flush all buffered messages)
Definition: logging.cpp:51
std::string GetLogPrefix(LogFlags category, Level level) const
Definition: logging.cpp:327
std::string LogLevelsString() const
Returns a string with all user-selectable log levels.
Definition: logging.cpp:273
void ShrinkDebugFile()
Definition: logging.cpp:406
bool m_print_to_file
Definition: logging.h:116
void SetCategoryLogLevel(const std::unordered_map< LogFlags, Level > &levels)
Definition: logging.h:166
bool m_print_to_console
Definition: logging.h:115
StdMutex m_cs
Definition: logging.h:86
void DisableCategory(LogFlags flag)
Definition: logging.cpp:112
static constexpr std::array< BCLog::Level, 3 > LogLevelsList()
Log severity levels that can be selected by the user.
Definition: logging.cpp:268
std::string LogCategoryToStr(BCLog::LogFlags category)
Definition: logging.cpp:232
static int FileWriteStr(const std::string &str, FILE *fp)
Definition: logging.cpp:46
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:201
bool fLogIPs
Definition: logging.cpp:44
static const std::unordered_map< BCLog::LogFlags, std::string > LOG_CATEGORIES_BY_FLAG
Definition: logging.cpp:186
const char *const DEFAULT_DEBUGLOGFILE
Definition: logging.cpp:20
static std::optional< BCLog::Level > GetLogLevel(const std::string &level_str)
Definition: logging.cpp:239
static const std::map< std::string, BCLog::LogFlags > LOG_CATEGORIES_BY_STR
Definition: logging.cpp:148
constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL
Definition: logging.cpp:21
BCLog::Logger & LogInstance()
Definition: logging.cpp:23
static const bool DEFAULT_LOGIPS
Definition: logging.h:24
#define LogPrintf(...)
Definition: logging.h:244
Definition: timer.h:19
Level
Definition: logging.h:74
std::string LogEscapeMessage(const std::string &str)
Belts and suspenders: make sure outgoing log messages don't contain potentially suspicious characters...
Definition: logging.cpp:313
LogFlags
Definition: logging.h:39
@ ESTIMATEFEE
Definition: logging.h:49
@ TXRECONCILIATION
Definition: logging.h:69
@ RAND
Definition: logging.h:54
@ BLOCKSTORAGE
Definition: logging.h:68
@ COINDB
Definition: logging.h:59
@ REINDEX
Definition: logging.h:52
@ TXPACKAGES
Definition: logging.h:71
@ WALLETDB
Definition: logging.h:47
@ SCAN
Definition: logging.h:70
@ ADDRMAN
Definition: logging.h:50
@ ALL
Definition: logging.h:72
@ 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
@ QT
Definition: logging.h:60
FILE * fopen(const fs::path &p, const char *mode)
Definition: fs.cpp:26
std::string ThreadGetInternalName()
Get the thread's internal (in-memory) name; used e.g.
Definition: threadnames.cpp:47
std::string ToString(const T &t)
Locale-independent version of std::to_string.
Definition: string.h:148
std::string RemovePrefix(std::string_view str, std::string_view prefix)
Definition: string.h:92
auto Join(const C &container, const S &separator, UnaryOp unary_op)
Join all container items.
Definition: string.h:107
std::string category
Definition: logging.h:34
#define LOCK(cs)
Definition: sync.h:257
std::chrono::seconds GetMockTime()
For testing.
Definition: time.cpp:39
std::string FormatISO8601DateTime(int64_t nTime)
ISO 8601 formatting is preferred.
Definition: time.cpp:46
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())