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