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