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