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