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 6251839 : 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 6251839 : static BCLog::Logger* g_logger{new BCLog::Logger()};
37 6251839 : return *g_logger;
38 0 : }
39 :
40 : bool fLogIPs = DEFAULT_LOGIPS;
41 :
42 2146836 : static int FileWriteStr(const std::string &str, FILE *fp)
43 : {
44 2146836 : return fwrite(str.data(), 1, str.size(), fp);
45 : }
46 :
47 627 : bool BCLog::Logger::StartLogging()
48 : {
49 627 : StdLockGuard scoped_lock(m_cs);
50 :
51 627 : assert(m_buffering);
52 627 : assert(m_fileout == nullptr);
53 :
54 627 : if (m_print_to_file) {
55 627 : assert(!m_file_path.empty());
56 627 : m_fileout = fsbridge::fopen(m_file_path, "a");
57 627 : if (!m_fileout) {
58 0 : return false;
59 : }
60 :
61 627 : setbuf(m_fileout, nullptr); // unbuffered
62 :
63 : // Add newlines to the logfile to distinguish this execution from the
64 : // last one.
65 627 : FileWriteStr("\n\n\n\n\n", m_fileout);
66 627 : }
67 :
68 : // dump buffered messages from before we opened the log
69 627 : m_buffering = false;
70 3162 : while (!m_msgs_before_open.empty()) {
71 2535 : const std::string& s = m_msgs_before_open.front();
72 :
73 2535 : if (m_print_to_file) FileWriteStr(s, m_fileout);
74 2535 : if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
75 5070 : for (const auto& cb : m_print_callbacks) {
76 2535 : cb(s);
77 : }
78 :
79 2535 : m_msgs_before_open.pop_front();
80 : }
81 627 : if (m_print_to_console) fflush(stdout);
82 :
83 627 : return true;
84 627 : }
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 630 : void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
96 : {
97 630 : m_categories |= flag;
98 630 : }
99 :
100 627 : bool BCLog::Logger::EnableCategory(const std::string& str)
101 : {
102 : BCLog::LogFlags flag;
103 627 : if (!GetLogCategory(flag, str)) return false;
104 627 : EnableCategory(flag);
105 627 : return true;
106 627 : }
107 :
108 1254 : void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
109 : {
110 1254 : m_categories &= ~flag;
111 1254 : }
112 :
113 1254 : bool BCLog::Logger::DisableCategory(const std::string& str)
114 : {
115 : BCLog::LogFlags flag;
116 1254 : if (!GetLogCategory(flag, str)) return false;
117 1254 : DisableCategory(flag);
118 1254 : return true;
119 1254 : }
120 :
121 2004793 : bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
122 : {
123 2004793 : return (m_categories.load(std::memory_order_relaxed) & category) != 0;
124 : }
125 :
126 1947260 : 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 1947260 : if (level >= BCLog::Level::Info) return true;
131 :
132 1947242 : if (!WillLogCategory(category)) return false;
133 :
134 1915379 : StdLockGuard scoped_lock(m_cs);
135 1915379 : const auto it{m_category_log_levels.find(category)};
136 1915379 : return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
137 1947260 : }
138 :
139 0 : bool BCLog::Logger::DefaultShrinkDebugFile() const
140 : {
141 0 : 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 1925 : bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
205 : {
206 1925 : if (str.empty()) {
207 627 : flag = BCLog::ALL;
208 627 : return true;
209 : }
210 27902 : for (const CLogCategoryDesc& category_desc : LogCategories) {
211 27902 : if (category_desc.category == str) {
212 1298 : flag = category_desc.flag;
213 1298 : return true;
214 : }
215 : }
216 0 : return false;
217 1925 : }
218 :
219 2532 : std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
220 : {
221 2532 : switch (level) {
222 : case BCLog::Level::Trace:
223 627 : return "trace";
224 : case BCLog::Level::Debug:
225 1256 : return "debug";
226 : case BCLog::Level::Info:
227 641 : return "info";
228 : case BCLog::Level::Warning:
229 4 : return "warning";
230 : case BCLog::Level::Error:
231 4 : return "error";
232 : }
233 0 : assert(false);
234 2532 : }
235 :
236 1883234 : std::string LogCategoryToStr(BCLog::LogFlags category)
237 : {
238 : // Each log category string representation should sync with LogCategories
239 1883234 : switch (category) {
240 : case BCLog::LogFlags::NONE:
241 0 : return "";
242 : case BCLog::LogFlags::NET:
243 1445 : return "net";
244 : case BCLog::LogFlags::TOR:
245 1 : return "tor";
246 : case BCLog::LogFlags::MEMPOOL:
247 24383 : return "mempool";
248 : case BCLog::LogFlags::HTTP:
249 2 : return "http";
250 : case BCLog::LogFlags::BENCHMARK:
251 1194524 : return "bench";
252 : case BCLog::LogFlags::ZMQ:
253 1 : return "zmq";
254 : case BCLog::LogFlags::WALLETDB:
255 31 : return "walletdb";
256 : case BCLog::LogFlags::RPC:
257 2 : return "rpc";
258 : case BCLog::LogFlags::ESTIMATEFEE:
259 24767 : return "estimatefee";
260 : case BCLog::LogFlags::ADDRMAN:
261 4672 : return "addrman";
262 : case BCLog::LogFlags::SELECTCOINS:
263 7819 : return "selectcoins";
264 : case BCLog::LogFlags::REINDEX:
265 1 : return "reindex";
266 : case BCLog::LogFlags::CMPCTBLOCK:
267 11 : return "cmpctblock";
268 : case BCLog::LogFlags::RANDOM:
269 1 : return "rand";
270 : case BCLog::LogFlags::PRUNE:
271 6 : return "prune";
272 : case BCLog::LogFlags::PROXY:
273 1 : return "proxy";
274 : case BCLog::LogFlags::MEMPOOLREJ:
275 1 : return "mempoolrej";
276 : case BCLog::LogFlags::LIBEVENT:
277 1 : return "libevent";
278 : case BCLog::LogFlags::COINDB:
279 359 : 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 204075 : return "validation";
286 : case BCLog::LogFlags::I2P:
287 33 : 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 6 : return "blockstorage";
296 : case BCLog::LogFlags::TXRECONCILIATION:
297 15 : return "txreconciliation";
298 : case BCLog::LogFlags::SCAN:
299 1 : return "scan";
300 : /* Start Dash */
301 : case BCLog::LogFlags::CHAINLOCKS:
302 1 : return "chainlocks";
303 : case BCLog::LogFlags::GOBJECT:
304 26416 : return "gobject";
305 : case BCLog::LogFlags::INSTANTSEND:
306 1 : return "instantsend";
307 : case BCLog::LogFlags::LLMQ:
308 75067 : return "llmq";
309 : case BCLog::LogFlags::LLMQ_DKG:
310 1 : return "llmq-dkg";
311 : case BCLog::LogFlags::LLMQ_SIGS:
312 1 : return "llmq-sigs";
313 : case BCLog::LogFlags::MNPAYMENTS:
314 225966 : return "mnpayments";
315 : case BCLog::LogFlags::MNSYNC:
316 1 : return "mnsync";
317 : case BCLog::LogFlags::COINJOIN:
318 6 : return "coinjoin";
319 : case BCLog::LogFlags::SPORK:
320 1 : return "spork";
321 : case BCLog::LogFlags::NETCONN:
322 1 : return "netconn";
323 : case BCLog::LogFlags::CREDITPOOL:
324 44593 : return "creditpool";
325 : case BCLog::LogFlags::EHF:
326 49015 : return "ehf";
327 : case BCLog::LogFlags::DASH:
328 0 : return "dash";
329 : case BCLog::LogFlags::NET_NETCONN:
330 3 : return "net|netconn";
331 : /* End Dash */
332 : case BCLog::LogFlags::ALL:
333 0 : return "all";
334 : }
335 0 : assert(false);
336 1883234 : }
337 :
338 633 : static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
339 : {
340 633 : if (level_str == "trace") {
341 629 : 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 633 : }
354 :
355 1439 : std::vector<LogCategory> BCLog::Logger::LogCategoriesList(bool enabled_only) const
356 : {
357 : // Sort log categories by alphabetical order.
358 1439 : std::array<CLogCategoryDesc, std::size(LogCategories)> categories;
359 1439 : std::copy(std::begin(LogCategories), std::end(LogCategories), categories.begin());
360 474870 : std::sort(categories.begin(), categories.end(), [](auto a, auto b) { return a.category < b.category; });
361 :
362 1439 : std::vector<LogCategory> ret;
363 66194 : for (const CLogCategoryDesc& category_desc : categories) {
364 64755 : if (category_desc.flag == BCLog::NONE || category_desc.flag == BCLog::ALL || category_desc.flag == BCLog::DASH) continue;
365 57560 : LogCategory catActive;
366 57560 : catActive.category = category_desc.category;
367 57560 : catActive.active = WillLogCategory(category_desc.flag);
368 57560 : if (!enabled_only || catActive.active) {
369 57560 : ret.push_back(catActive);
370 57560 : }
371 57560 : }
372 1439 : return ret;
373 1439 : }
374 :
375 : /** Log severity levels that can be selected by the user. */
376 627 : static constexpr std::array<BCLog::Level, 3> LogLevelsList()
377 : {
378 627 : return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
379 : }
380 :
381 627 : std::string BCLog::Logger::LogLevelsString() const
382 : {
383 627 : const auto& levels = LogLevelsList();
384 2508 : return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
385 0 : }
386 :
387 2146212 : std::string BCLog::Logger::LogTimestampStr(const std::string& str)
388 : {
389 2146212 : std::string strStamped;
390 :
391 2146212 : if (!m_log_timestamps)
392 68 : return str;
393 :
394 2146144 : if (m_started_new_line) {
395 2146135 : int64_t nTimeMicros = GetTimeMicros();
396 2146135 : strStamped = FormatISO8601DateTime(nTimeMicros/1000000);
397 2146135 : if (m_log_time_micros && !strStamped.empty()) {
398 2146016 : strStamped.pop_back();
399 2146016 : strStamped += strprintf(".%06dZ", nTimeMicros%1000000);
400 2146016 : }
401 2146135 : std::chrono::seconds mocktime = GetMockTime();
402 2146135 : if (mocktime > 0s) {
403 2018914 : strStamped += strprintf(" (mocktime: %d)", count_seconds(mocktime));
404 2018914 : }
405 2146135 : strStamped += ' ' + str;
406 2146135 : } else
407 9 : strStamped = str;
408 :
409 2146144 : return strStamped;
410 2146212 : }
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 2146216 : std::string LogEscapeMessage(const std::string& str) {
421 2146216 : std::string ret;
422 189653539 : for (char ch_in : str) {
423 187507323 : uint8_t ch = (uint8_t)ch_in;
424 187507323 : if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
425 187507319 : ret += ch_in;
426 187507319 : } else {
427 4 : ret += strprintf("\\x%02x", ch);
428 : }
429 : }
430 2146216 : return ret;
431 2146216 : }
432 : } // namespace BCLog
433 :
434 2146203 : std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
435 : {
436 2146203 : if (category == LogFlags::NONE) category = LogFlags::ALL;
437 :
438 2146203 : const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
439 :
440 : // If there is no category, Info is implied
441 2146203 : if (!has_category && level == Level::Info) return {};
442 :
443 1883238 : std::string s{"["};
444 1883238 : if (has_category) {
445 1883234 : s += LogCategoryToStr(category);
446 1883234 : }
447 :
448 1883238 : 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 1883238 : if (has_category) s += ":";
453 1883238 : s += Logger::LogLevelToStr(level);
454 24 : }
455 :
456 24 : s += "] ";
457 1883238 : return s;
458 7795869 : }
459 :
460 2146212 : 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 2146212 : StdLockGuard scoped_lock(m_cs);
463 2146212 : std::string str_prefixed = LogEscapeMessage(str);
464 :
465 2146212 : if (m_started_new_line) {
466 2146203 : str_prefixed.insert(0, GetLogPrefix(category, level));
467 2146203 : }
468 :
469 2146212 : if (m_log_sourcelocations && m_started_new_line) {
470 2146023 : str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
471 2146023 : }
472 :
473 2146212 : if (m_log_threadnames && m_started_new_line) {
474 2146016 : const auto& threadname = util::ThreadGetInternalName();
475 : // 16 chars total, "dash-" is 5 of them and another 1 is a NUL terminator
476 2146016 : str_prefixed.insert(0, "[" + strprintf("%10s", (threadname.empty() ? "unknown" : threadname)) + "] ");
477 2146016 : }
478 :
479 2146212 : str_prefixed = LogTimestampStr(str_prefixed);
480 :
481 2146212 : m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
482 :
483 2146212 : if (m_buffering) {
484 : // buffer if we haven't started logging yet
485 2538 : m_msgs_before_open.push_back(str_prefixed);
486 2538 : return;
487 : }
488 :
489 2143674 : 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 4288176 : for (const auto& cb : m_print_callbacks) {
495 2144502 : cb(str_prefixed);
496 : }
497 2143674 : if (m_print_to_file) {
498 2143674 : assert(m_fileout != nullptr);
499 :
500 : // reopen the log file, if requested
501 2143674 : 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 2143674 : FileWriteStr(str_prefixed, m_fileout);
511 2143674 : }
512 2146212 : }
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 629 : bool BCLog::Logger::SetLogLevel(const std::string& level_str)
556 : {
557 629 : const auto level = GetLogLevel(level_str);
558 629 : if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
559 629 : m_log_level = level.value();
560 629 : return true;
561 629 : }
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 : }
|
