logging.cpp raw
1 // Copyright (c) 2009-2010 Satoshi Nakamoto
2 // Copyright (c) 2009-present 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 <memusage.h>
8 #include <util/check.h>
9 #include <util/fs.h>
10 #include <util/string.h>
11 #include <util/threadnames.h>
12 #include <util/time.h>
13
14 #include <array>
15 #include <cstring>
16 #include <map>
17 #include <optional>
18 #include <utility>
19
20 using util::Join;
21 using util::RemovePrefixView;
22
23 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
24 constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
25
26 BCLog::Logger& LogInstance()
27 {
28 /**
29 * NOTE: the logger instances is leaked on exit. This is ugly, but will be
30 * cleaned up by the OS/libc. Defining a logger as a global object doesn't work
31 * since the order of destruction of static/global objects is undefined.
32 * Consider if the logger gets destroyed, and then some later destructor calls
33 * LogInfo, maybe indirectly, and you get a core dump at shutdown trying to
34 * access the logger. When the shutdown sequence is fully audited and tested,
35 * explicit destruction of these objects can be implemented by changing this
36 * from a raw pointer to a std::unique_ptr.
37 * Since the ~Logger() destructor is never called, the Logger class and all
38 * its subclasses must have implicitly-defined destructors.
39 *
40 * This method of initialization was originally introduced in
41 * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
42 */
43 static BCLog::Logger* g_logger{new BCLog::Logger()};
44 return *g_logger;
45 }
46
47 bool fLogIPs = DEFAULT_LOGIPS;
48
49 static int FileWriteStr(std::string_view str, FILE *fp)
50 {
51 return fwrite(str.data(), 1, str.size(), fp);
52 }
53
54 bool BCLog::Logger::StartLogging()
55 {
56 STDLOCK(m_cs);
57
58 assert(m_buffering);
59 assert(m_fileout == nullptr);
60
61 if (m_print_to_file) {
62 assert(!m_file_path.empty());
63 m_fileout = fsbridge::fopen(m_file_path, "a");
64 if (!m_fileout) {
65 return false;
66 }
67
68 setbuf(m_fileout, nullptr); // unbuffered
69
70 // Add newlines to the logfile to distinguish this execution from the
71 // last one.
72 FileWriteStr("\n\n\n\n\n", m_fileout);
73 }
74
75 // dump buffered messages from before we opened the log
76 m_buffering = false;
77 if (m_buffer_lines_discarded > 0) {
78 LogPrint_({
79 .category = BCLog::ALL,
80 .level = Level::Info,
81 .should_ratelimit = false,
82 .source_loc = SourceLocation{__func__},
83 .message = strprintf("Early logging buffer overflowed, %d log lines discarded.", m_buffer_lines_discarded),
84 });
85 }
86 while (!m_msgs_before_open.empty()) {
87 const auto& buflog = m_msgs_before_open.front();
88 std::string s{Format(buflog)};
89 m_msgs_before_open.pop_front();
90
91 if (m_print_to_file) FileWriteStr(s, m_fileout);
92 if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
93 for (const auto& cb : m_print_callbacks) {
94 cb(s);
95 }
96 }
97 m_cur_buffer_memusage = 0;
98 if (m_print_to_console) fflush(stdout);
99
100 return true;
101 }
102
103 void BCLog::Logger::DisconnectTestLogger()
104 {
105 STDLOCK(m_cs);
106 m_buffering = true;
107 if (m_fileout != nullptr) fclose(m_fileout);
108 m_fileout = nullptr;
109 m_print_callbacks.clear();
110 m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
111 m_cur_buffer_memusage = 0;
112 m_buffer_lines_discarded = 0;
113 m_msgs_before_open.clear();
114 }
115
116 void BCLog::Logger::DisableLogging()
117 {
118 {
119 STDLOCK(m_cs);
120 assert(m_buffering);
121 assert(m_print_callbacks.empty());
122 }
123 m_print_to_file = false;
124 m_print_to_console = false;
125 StartLogging();
126 }
127
128 void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
129 {
130 m_categories |= flag;
131 }
132
133 bool BCLog::Logger::EnableCategory(std::string_view str)
134 {
135 if (const auto flag{GetLogCategory(str)}) {
136 EnableCategory(*flag);
137 return true;
138 }
139 return false;
140 }
141
142 void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
143 {
144 m_categories &= ~flag;
145 }
146
147 bool BCLog::Logger::DisableCategory(std::string_view str)
148 {
149 if (const auto flag{GetLogCategory(str)}) {
150 DisableCategory(*flag);
151 return true;
152 }
153 return false;
154 }
155
156 bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
157 {
158 return (m_categories.load(std::memory_order_relaxed) & category) != 0;
159 }
160
161 bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
162 {
163 // Log messages at Info, Warning and Error level unconditionally, so that
164 // important troubleshooting information doesn't get lost.
165 if (level >= BCLog::Level::Info) return true;
166
167 if (!WillLogCategory(category)) return false;
168
169 STDLOCK(m_cs);
170 const auto it{m_category_log_levels.find(category)};
171 return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
172 }
173
174 bool BCLog::Logger::DefaultShrinkDebugFile() const
175 {
176 return m_categories == BCLog::NONE;
177 }
178
179 static const std::map<std::string, BCLog::LogFlags, std::less<>> LOG_CATEGORIES_BY_STR{
180 {"net", BCLog::NET},
181 {"tor", BCLog::TOR},
182 {"mempool", BCLog::MEMPOOL},
183 {"http", BCLog::HTTP},
184 {"bench", BCLog::BENCH},
185 {"zmq", BCLog::ZMQ},
186 {"walletdb", BCLog::WALLETDB},
187 {"rpc", BCLog::RPC},
188 {"estimatefee", BCLog::ESTIMATEFEE},
189 {"addrman", BCLog::ADDRMAN},
190 {"selectcoins", BCLog::SELECTCOINS},
191 {"reindex", BCLog::REINDEX},
192 {"cmpctblock", BCLog::CMPCTBLOCK},
193 {"rand", BCLog::RAND},
194 {"prune", BCLog::PRUNE},
195 {"proxy", BCLog::PROXY},
196 {"mempoolrej", BCLog::MEMPOOLREJ},
197 {"coindb", BCLog::COINDB},
198 {"qt", BCLog::QT},
199 {"leveldb", BCLog::LEVELDB},
200 {"validation", BCLog::VALIDATION},
201 {"i2p", BCLog::I2P},
202 {"ipc", BCLog::IPC},
203 #ifdef DEBUG_LOCKCONTENTION
204 {"lock", BCLog::LOCK},
205 #endif
206 {"blockstorage", BCLog::BLOCKSTORAGE},
207 {"txreconciliation", BCLog::TXRECONCILIATION},
208 {"scan", BCLog::SCAN},
209 {"txpackages", BCLog::TXPACKAGES},
210 {"kernel", BCLog::KERNEL},
211 {"privatebroadcast", BCLog::PRIVBROADCAST},
212 };
213
214 static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
215 // Swap keys and values from LOG_CATEGORIES_BY_STR.
216 [](const auto& in) {
217 std::unordered_map<BCLog::LogFlags, std::string> out;
218 for (const auto& [k, v] : in) {
219 const bool inserted{out.emplace(v, k).second};
220 assert(inserted);
221 }
222 return out;
223 }(LOG_CATEGORIES_BY_STR)
224 };
225
226 std::optional<BCLog::LogFlags> BCLog::Logger::GetLogCategory(std::string_view str)
227 {
228 if (str.empty() || str == "1" || str == "all") {
229 return BCLog::ALL;
230 }
231 auto it = LOG_CATEGORIES_BY_STR.find(str);
232 if (it != LOG_CATEGORIES_BY_STR.end()) {
233 return it->second;
234 }
235 if (str == "libevent") {
236 LogWarning("The logging category `%s` is deprecated, does nothing, and will be removed in a future version", str);
237 return BCLog::NONE;
238 }
239 return std::nullopt;
240 }
241
242 std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
243 {
244 switch (level) {
245 case BCLog::Level::Trace:
246 return "trace";
247 case BCLog::Level::Debug:
248 return "debug";
249 case BCLog::Level::Info:
250 return "info";
251 case BCLog::Level::Warning:
252 return "warning";
253 case BCLog::Level::Error:
254 return "error";
255 }
256 assert(false);
257 }
258
259 static std::string LogCategoryToStr(BCLog::LogFlags category)
260 {
261 if (category == BCLog::ALL) {
262 return "all";
263 }
264 auto it = LOG_CATEGORIES_BY_FLAG.find(category);
265 assert(it != LOG_CATEGORIES_BY_FLAG.end());
266 return it->second;
267 }
268
269 static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str)
270 {
271 if (level_str == "trace") {
272 return BCLog::Level::Trace;
273 } else if (level_str == "debug") {
274 return BCLog::Level::Debug;
275 } else if (level_str == "info") {
276 return BCLog::Level::Info;
277 } else if (level_str == "warning") {
278 return BCLog::Level::Warning;
279 } else if (level_str == "error") {
280 return BCLog::Level::Error;
281 } else {
282 return std::nullopt;
283 }
284 }
285
286 std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
287 {
288 std::vector<LogCategory> ret;
289 ret.reserve(LOG_CATEGORIES_BY_STR.size());
290 for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
291 ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
292 }
293 return ret;
294 }
295
296 /** Log severity levels that can be selected by the user. */
297 static constexpr std::array<BCLog::Level, 3> LogLevelsList()
298 {
299 return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
300 }
301
302 std::string BCLog::Logger::LogLevelsString() const
303 {
304 const auto& levels = LogLevelsList();
305 return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
306 }
307
308 std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const
309 {
310 std::string strStamped;
311
312 if (!m_log_timestamps)
313 return strStamped;
314
315 const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
316 strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
317 if (m_log_time_micros && !strStamped.empty()) {
318 strStamped.pop_back();
319 strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
320 }
321 if (mocktime > 0s) {
322 strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
323 }
324 strStamped += ' ';
325
326 return strStamped;
327 }
328
329 namespace BCLog {
330 /** Belts and suspenders: make sure outgoing log messages don't contain
331 * potentially suspicious characters, such as terminal control codes.
332 *
333 * This escapes control characters except newline ('\n') in C syntax.
334 * It escapes instead of removes them to still allow for troubleshooting
335 * issues where they accidentally end up in strings.
336 */
337 std::string LogEscapeMessage(std::string_view str) {
338 std::string ret;
339 for (char ch_in : str) {
340 uint8_t ch = (uint8_t)ch_in;
341 if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
342 ret += ch_in;
343 } else {
344 ret += strprintf("\\x%02x", ch);
345 }
346 }
347 return ret;
348 }
349 } // namespace BCLog
350
351 std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
352 {
353 if (category == LogFlags::NONE) category = LogFlags::ALL;
354
355 const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
356
357 // If there is no category, Info is implied
358 if (!has_category && level == Level::Info) return {};
359
360 std::string s{"["};
361 if (has_category) {
362 s += LogCategoryToStr(category);
363 }
364
365 if (m_always_print_category_level || !has_category || level != Level::Debug) {
366 // If there is a category, Debug is implied, so don't add the level
367
368 // Only add separator if we have a category
369 if (has_category) s += ":";
370 s += Logger::LogLevelToStr(level);
371 }
372
373 s += "] ";
374 return s;
375 }
376
377 static size_t MemUsage(const util::log::Entry& log)
378 {
379 return memusage::DynamicUsage(log.message) +
380 memusage::DynamicUsage(log.thread_name) +
381 memusage::MallocUsage(sizeof(memusage::list_node<util::log::Entry>));
382 }
383
384 BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
385 : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
386
387 std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
388 SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
389 {
390 auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
391 std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
392 auto reset = [weak_limiter] {
393 if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
394 };
395 scheduler_func(reset, limiter->m_reset_window);
396 return limiter;
397 }
398
399 BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
400 const SourceLocation& source_loc,
401 const std::string& str)
402 {
403 STDLOCK(m_mutex);
404 auto& stats{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second};
405 Status status{stats.m_dropped_bytes > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED};
406
407 if (!stats.Consume(str.size()) && status == Status::UNSUPPRESSED) {
408 status = Status::NEWLY_SUPPRESSED;
409 m_suppression_active = true;
410 }
411
412 return status;
413 }
414
415 std::string BCLog::Logger::Format(const util::log::Entry& entry) const
416 {
417 std::string result{LogTimestampStr(entry.timestamp, entry.mocktime)};
418
419 if (m_log_threadnames) {
420 result += strprintf("[%s] ", (entry.thread_name.empty() ? "unknown" : entry.thread_name));
421 }
422
423 if (m_log_sourcelocations) {
424 result += strprintf("[%s:%d] [%s] ", RemovePrefixView(entry.source_loc.file_name(), "./"), entry.source_loc.line(), entry.source_loc.function_name_short());
425 }
426
427 result += GetLogPrefix(static_cast<LogFlags>(entry.category), entry.level);
428 result += LogEscapeMessage(entry.message);
429
430 if (!result.ends_with('\n')) result += '\n';
431 return result;
432 }
433
434 void BCLog::Logger::LogPrint(util::log::Entry entry)
435 {
436 STDLOCK(m_cs);
437 return LogPrint_(std::move(entry));
438 }
439
440 // NOLINTNEXTLINE(misc-no-recursion)
441 void BCLog::Logger::LogPrint_(util::log::Entry entry)
442 {
443 if (m_buffering) {
444 {
445 m_cur_buffer_memusage += MemUsage(entry);
446 m_msgs_before_open.push_back(std::move(entry));
447 }
448
449 while (m_cur_buffer_memusage > m_max_buffer_memusage) {
450 if (m_msgs_before_open.empty()) {
451 m_cur_buffer_memusage = 0;
452 break;
453 }
454 m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
455 m_msgs_before_open.pop_front();
456 ++m_buffer_lines_discarded;
457 }
458
459 return;
460 }
461
462 std::string str_prefixed{Format(entry)};
463 bool ratelimit{false};
464 if (entry.should_ratelimit && m_limiter) {
465 auto status{m_limiter->Consume(entry.source_loc, str_prefixed)};
466 if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
467 // NOLINTNEXTLINE(misc-no-recursion)
468 LogPrint_({
469 .category = LogFlags::ALL,
470 .level = Level::Warning,
471 .should_ratelimit = false, // with should_ratelimit=false, this cannot lead to infinite recursion
472 .source_loc = SourceLocation{__func__},
473 .message = strprintf(
474 "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
475 "the last time window of %is. Suppressing logging to disk from this "
476 "source location until time window resets. Console logging "
477 "unaffected. Last log entry.",
478 entry.source_loc.file_name(), entry.source_loc.line(), entry.source_loc.function_name_short(),
479 m_limiter->m_max_bytes,
480 Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
481 });
482 } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
483 ratelimit = true;
484 }
485 }
486
487 // To avoid confusion caused by dropped log messages when debugging an issue,
488 // we prefix log lines with "[*]" when there are any suppressed source locations.
489 if (m_limiter && m_limiter->SuppressionsActive()) {
490 str_prefixed.insert(0, "[*] ");
491 }
492
493 if (m_print_to_console) {
494 // print to console
495 fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
496 fflush(stdout);
497 }
498 for (const auto& cb : m_print_callbacks) {
499 cb(str_prefixed);
500 }
501 if (m_print_to_file && !ratelimit) {
502 assert(m_fileout != nullptr);
503
504 // reopen the log file, if requested
505 if (m_reopen_file) {
506 m_reopen_file = false;
507 FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
508 if (new_fileout) {
509 setbuf(new_fileout, nullptr); // unbuffered
510 fclose(m_fileout);
511 m_fileout = new_fileout;
512 }
513 }
514 FileWriteStr(str_prefixed, m_fileout);
515 }
516 }
517
518 void BCLog::Logger::ShrinkDebugFile()
519 {
520 STDLOCK(m_cs);
521
522 // Amount of debug.log to save at end when shrinking (must fit in memory)
523 constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
524
525 assert(!m_file_path.empty());
526
527 // Scroll debug.log if it's getting too big
528 FILE* file = fsbridge::fopen(m_file_path, "r");
529
530 // Special files (e.g. device nodes) may not have a size.
531 size_t log_size = 0;
532 try {
533 log_size = fs::file_size(m_file_path);
534 } catch (const fs::filesystem_error&) {}
535
536 // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
537 // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
538 if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
539 {
540 // Restart the file with some of the end
541 std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
542 if (fseek(file, -((long)vch.size()), SEEK_END)) {
543 // LogWarning, except with m_cs held
544 LogPrint_({
545 .category = BCLog::ALL,
546 .level = Level::Warning,
547 .should_ratelimit = true,
548 .source_loc = SourceLocation{__func__},
549 .message = "Failed to shrink debug log file: fseek(...) failed",
550 });
551 fclose(file);
552 return;
553 }
554 int nBytes = fread(vch.data(), 1, vch.size(), file);
555 fclose(file);
556
557 file = fsbridge::fopen(m_file_path, "w");
558 if (file)
559 {
560 fwrite(vch.data(), 1, nBytes, file);
561 fclose(file);
562 }
563 }
564 else if (file != nullptr)
565 fclose(file);
566 }
567
568 void BCLog::LogRateLimiter::Reset()
569 {
570 decltype(m_source_locations) source_locations;
571 {
572 STDLOCK(m_mutex);
573 source_locations.swap(m_source_locations);
574 m_suppression_active = false;
575 }
576 for (const auto& [source_loc, stats] : source_locations) {
577 if (stats.m_dropped_bytes == 0) continue;
578 LogWarning(util::log::NO_RATE_LIMIT,
579 "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.",
580 source_loc.file_name(), source_loc.line(), source_loc.function_name_short(),
581 stats.m_dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
582 }
583 }
584
585 bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes)
586 {
587 if (bytes > m_available_bytes) {
588 m_dropped_bytes += bytes;
589 m_available_bytes = 0;
590 return false;
591 }
592
593 m_available_bytes -= bytes;
594 return true;
595 }
596
597 bool BCLog::Logger::SetLogLevel(std::string_view level_str)
598 {
599 const auto level = GetLogLevel(level_str);
600 if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
601 m_log_level = level.value();
602 return true;
603 }
604
605 bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str)
606 {
607 const auto flag{GetLogCategory(category_str)};
608 if (!flag) return false;
609
610 const auto level = GetLogLevel(level_str);
611 if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
612 if (*flag == BCLog::NONE) return true;
613
614 STDLOCK(m_cs);
615 m_category_log_levels[*flag] = level.value();
616 return true;
617 }
618
619 bool util::log::ShouldDebugLog(Category category)
620 {
621 return LogInstance().WillLogCategoryLevel(static_cast<BCLog::LogFlags>(category), util::log::Level::Debug);
622 }
623
624 bool util::log::ShouldTraceLog(Category category)
625 {
626 return LogInstance().WillLogCategoryLevel(static_cast<BCLog::LogFlags>(category), util::log::Level::Trace);
627 }
628
629 void util::log::Log(util::log::Entry entry)
630 {
631 BCLog::Logger& logger{LogInstance()};
632 if (logger.Enabled()) {
633 logger.LogPrint(std::move(entry));
634 }
635 }
636