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 : :
23 : : const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
24 : : constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
25 : :
26 : 61868686 : 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 [ + + + - : 61868686 : static BCLog::Logger* g_logger{new BCLog::Logger()};
+ - ]
44 : 61868686 : return *g_logger;
45 : : }
46 : :
47 : : bool fLogIPs = DEFAULT_LOGIPS;
48 : :
49 : 5035617 : static int FileWriteStr(std::string_view str, FILE *fp)
50 : : {
51 : 5035617 : return fwrite(str.data(), 1, str.size(), fp);
52 : : }
53 : :
54 : 1574 : bool BCLog::Logger::StartLogging()
55 : : {
56 : 1574 : StdLockGuard scoped_lock(m_cs);
57 : :
58 [ - + ]: 1574 : assert(m_buffering);
59 [ - + ]: 1574 : assert(m_fileout == nullptr);
60 : :
61 [ + + ]: 1574 : if (m_print_to_file) {
62 [ - + ]: 1485 : assert(!m_file_path.empty());
63 [ + - ]: 1485 : m_fileout = fsbridge::fopen(m_file_path, "a");
64 [ + - ]: 1485 : if (!m_fileout) {
65 : : return false;
66 : : }
67 : :
68 : 1485 : setbuf(m_fileout, nullptr); // unbuffered
69 : :
70 : : // Add newlines to the logfile to distinguish this execution from the
71 : : // last one.
72 [ + - ]: 1485 : FileWriteStr("\n\n\n\n\n", m_fileout);
73 : : }
74 : :
75 : : // dump buffered messages from before we opened the log
76 : 1574 : m_buffering = false;
77 [ - + ]: 1574 : if (m_buffer_lines_discarded > 0) {
78 [ # # # # ]: 0 : 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 [ + + ]: 4719 : while (!m_msgs_before_open.empty()) {
81 [ - + ]: 3145 : const auto& buflog = m_msgs_before_open.front();
82 [ - + ]: 3145 : std::string s{buflog.str};
83 [ - + + - ]: 3145 : FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime);
84 : 3145 : m_msgs_before_open.pop_front();
85 : :
86 [ + + - + : 3145 : if (m_print_to_file) FileWriteStr(s, m_fileout);
+ - ]
87 [ - + - - : 3145 : if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
- - ]
88 [ - + ]: 3145 : for (const auto& cb : m_print_callbacks) {
89 [ # # ]: 0 : cb(s);
90 : : }
91 : 3145 : }
92 : 1574 : m_cur_buffer_memusage = 0;
93 [ - + - - ]: 1574 : if (m_print_to_console) fflush(stdout);
94 : :
95 : : return true;
96 : 1574 : }
97 : :
98 : 1572 : void BCLog::Logger::DisconnectTestLogger()
99 : : {
100 : 1572 : StdLockGuard scoped_lock(m_cs);
101 : 1572 : m_buffering = true;
102 [ + + + - ]: 1572 : if (m_fileout != nullptr) fclose(m_fileout);
103 : 1572 : m_fileout = nullptr;
104 : 1572 : m_print_callbacks.clear();
105 : 1572 : m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
106 : 1572 : m_cur_buffer_memusage = 0;
107 : 1572 : m_buffer_lines_discarded = 0;
108 : 1572 : m_msgs_before_open.clear();
109 : 1572 : }
110 : :
111 : 2 : void BCLog::Logger::DisableLogging()
112 : : {
113 : 2 : {
114 : 2 : StdLockGuard scoped_lock(m_cs);
115 [ - + ]: 2 : assert(m_buffering);
116 [ - + ]: 2 : assert(m_print_callbacks.empty());
117 : 2 : }
118 : 2 : m_print_to_file = false;
119 : 2 : m_print_to_console = false;
120 : 2 : StartLogging();
121 : 2 : }
122 : :
123 : 1905 : void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
124 : : {
125 : 1905 : m_categories |= flag;
126 : 1905 : }
127 : :
128 : 1939 : bool BCLog::Logger::EnableCategory(std::string_view str)
129 : : {
130 : 1939 : BCLog::LogFlags flag;
131 [ + + ]: 1939 : if (!GetLogCategory(flag, str)) return false;
132 : 1905 : EnableCategory(flag);
133 : 1905 : return true;
134 : : }
135 : :
136 : 3581 : void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
137 : : {
138 : 3581 : m_categories &= ~flag;
139 : 3581 : }
140 : :
141 : 3603 : bool BCLog::Logger::DisableCategory(std::string_view str)
142 : : {
143 : 3603 : BCLog::LogFlags flag;
144 [ + + ]: 3603 : if (!GetLogCategory(flag, str)) return false;
145 : 3581 : DisableCategory(flag);
146 : 3581 : return true;
147 : : }
148 : :
149 : 48919850 : bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
150 : : {
151 : 48919850 : return (m_categories.load(std::memory_order_relaxed) & category) != 0;
152 : : }
153 : :
154 : 48827661 : 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 [ + + ]: 48827661 : if (level >= BCLog::Level::Info) return true;
159 : :
160 [ + + ]: 48825717 : if (!WillLogCategory(category)) return false;
161 : :
162 : 4663969 : StdLockGuard scoped_lock(m_cs);
163 : 4663969 : const auto it{m_category_log_levels.find(category)};
164 [ + - ]: 4663969 : return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
165 : 4663969 : }
166 : :
167 : 0 : bool BCLog::Logger::DefaultShrinkDebugFile() const
168 : : {
169 : 0 : 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 : 228 : [](const auto& in) {
209 : 228 : std::unordered_map<BCLog::LogFlags, std::string> out;
210 [ + - + + ]: 6612 : for (const auto& [k, v] : in) {
211 : 6384 : const bool inserted{out.emplace(v, k).second};
212 [ - + ]: 6384 : assert(inserted);
213 : : }
214 : 228 : return out;
215 : 0 : }(LOG_CATEGORIES_BY_STR)
216 : : };
217 : :
218 : 5542 : bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str)
219 : : {
220 [ + + + + : 5542 : if (str.empty() || str == "1" || str == "all") {
+ + ]
221 : 2155 : flag = BCLog::ALL;
222 : 2155 : return true;
223 : : }
224 : 3387 : auto it = LOG_CATEGORIES_BY_STR.find(str);
225 [ + + ]: 3387 : if (it != LOG_CATEGORIES_BY_STR.end()) {
226 : 3331 : flag = it->second;
227 : 3331 : return true;
228 : : }
229 : : return false;
230 : : }
231 : :
232 : 40457 : std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
233 : : {
234 [ + + + - : 40457 : switch (level) {
+ - ]
235 : 1572 : case BCLog::Level::Trace:
236 : 1572 : return "trace";
237 : 3144 : case BCLog::Level::Debug:
238 : 3144 : return "debug";
239 : 1572 : case BCLog::Level::Info:
240 : 1572 : return "info";
241 : 0 : case BCLog::Level::Warning:
242 : 0 : return "warning";
243 : 34169 : case BCLog::Level::Error:
244 : 34169 : return "error";
245 : : }
246 : 0 : assert(false);
247 : : }
248 : :
249 : 4661067 : static std::string LogCategoryToStr(BCLog::LogFlags category)
250 : : {
251 [ - + ]: 4661067 : if (category == BCLog::ALL) {
252 : 0 : return "all";
253 : : }
254 : 4661067 : auto it = LOG_CATEGORIES_BY_FLAG.find(category);
255 [ - + ]: 4661067 : assert(it != LOG_CATEGORIES_BY_FLAG.end());
256 [ - + ]: 4661067 : return it->second;
257 : : }
258 : :
259 : 1572 : static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str)
260 : : {
261 [ + - ]: 1572 : if (level_str == "trace") {
262 : 1572 : return BCLog::Level::Trace;
263 [ # # ]: 0 : } else if (level_str == "debug") {
264 : 0 : return BCLog::Level::Debug;
265 [ # # ]: 0 : } else if (level_str == "info") {
266 : 0 : return BCLog::Level::Info;
267 [ # # ]: 0 : } else if (level_str == "warning") {
268 : 0 : return BCLog::Level::Warning;
269 [ # # ]: 0 : } else if (level_str == "error") {
270 : 0 : return BCLog::Level::Error;
271 : : } else {
272 : 0 : return std::nullopt;
273 : : }
274 : : }
275 : :
276 : 3361 : std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
277 : : {
278 : 3361 : std::vector<LogCategory> ret;
279 [ + - ]: 3361 : ret.reserve(LOG_CATEGORIES_BY_STR.size());
280 [ - + + + ]: 97469 : for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
281 [ - + + - : 188216 : ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
+ - ]
282 : : }
283 : 3361 : return ret;
284 : 0 : }
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 : 1572 : std::string BCLog::Logger::LogLevelsString() const
293 : : {
294 : 1572 : const auto& levels = LogLevelsList();
295 [ + - + - ]: 7860 : return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
296 : : }
297 : :
298 : 5034306 : std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const
299 : : {
300 [ + - ]: 5034306 : std::string strStamped;
301 : :
302 [ + - ]: 5034306 : if (!m_log_timestamps)
303 : : return strStamped;
304 : :
305 : 5034306 : const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
306 [ + - ]: 5034306 : strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
307 [ + + + - ]: 5034306 : if (m_log_time_micros && !strStamped.empty()) {
308 : 5034304 : strStamped.pop_back();
309 [ + - ]: 10068608 : strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
310 : : }
311 [ + + ]: 5034306 : if (mocktime > 0s) {
312 [ + - + - : 15098199 : strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
- + ]
313 : : }
314 [ + - ]: 10068612 : strStamped += ' ';
315 : :
316 : : return strStamped;
317 : 0 : }
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 : 5051765 : std::string LogEscapeMessage(std::string_view str) {
328 : 5051765 : std::string ret;
329 [ + + ]: 399442844 : for (char ch_in : str) {
330 : 394391079 : uint8_t ch = (uint8_t)ch_in;
331 [ + - + - ]: 394391079 : if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
332 [ + - ]: 788782158 : ret += ch_in;
333 : : } else {
334 [ # # ]: 0 : ret += strprintf("\\x%02x", ch);
335 : : }
336 : : }
337 : 5051765 : return ret;
338 : 0 : }
339 : : } // namespace BCLog
340 : :
341 : 5034306 : std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
342 : : {
343 [ - + ]: 5034306 : if (category == LogFlags::NONE) category = LogFlags::ALL;
344 : :
345 [ + - + + ]: 5034306 : const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
346 : :
347 : : // If there is no category, Info is implied
348 [ + + ]: 5034306 : if (!has_category && level == Level::Info) return {};
349 : :
350 : 4695236 : std::string s{"["};
351 [ + + ]: 4695236 : if (has_category) {
352 [ + - ]: 9322134 : s += LogCategoryToStr(category);
353 : : }
354 : :
355 [ + - + + ]: 4695236 : 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 [ - + - - ]: 34169 : if (has_category) s += ":";
360 [ + - ]: 68338 : s += Logger::LogLevelToStr(level);
361 : : }
362 : :
363 [ + - ]: 4695236 : s += "] ";
364 : 4695236 : return s;
365 : 4695236 : }
366 : :
367 : 23964 : static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog)
368 : : {
369 : 23964 : return memusage::DynamicUsage(buflog.str) +
370 : 23964 : memusage::DynamicUsage(buflog.threadname) +
371 : 23964 : memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
372 : : }
373 : :
374 : 0 : BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
375 : 0 : : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
376 : :
377 : 0 : std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
378 : : SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
379 : : {
380 [ # # ]: 0 : auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
381 [ # # ]: 0 : std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
382 [ # # # # : 0 : auto reset = [weak_limiter] {
# # # # #
# ]
383 [ # # # # ]: 0 : if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
384 : 0 : };
385 [ # # # # ]: 0 : scheduler_func(reset, limiter->m_reset_window);
386 [ # # ]: 0 : return limiter;
387 [ # # ]: 0 : }
388 : :
389 : 0 : BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
390 : : const std::source_location& source_loc,
391 : : const std::string& str)
392 : : {
393 : 0 : StdLockGuard scoped_lock(m_mutex);
394 [ # # ]: 0 : auto& stats{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second};
395 [ # # ]: 0 : Status status{stats.m_dropped_bytes > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED};
396 : :
397 [ # # # # : 0 : if (!stats.Consume(str.size()) && status == Status::UNSUPPRESSED) {
# # # # ]
398 : 0 : status = Status::NEWLY_SUPPRESSED;
399 : 0 : m_suppression_active = true;
400 : : }
401 : :
402 : 0 : return status;
403 : 0 : }
404 : :
405 : 5034306 : 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 [ - + ]: 5211487 : if (!str.ends_with('\n')) str.push_back('\n');
408 : :
409 [ + - ]: 5034306 : str.insert(0, GetLogPrefix(category, level));
410 : :
411 [ + + ]: 5034306 : if (m_log_sourcelocations) {
412 [ + - + - : 25171520 : str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name()));
+ - + - ]
413 : : }
414 : :
415 [ + + ]: 5034306 : if (m_log_threadnames) {
416 [ + + + - ]: 10068608 : str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname)));
417 : : }
418 : :
419 [ + - ]: 5034306 : str.insert(0, LogTimestampStr(now, mocktime));
420 : 5034306 : }
421 : :
422 : 5051765 : void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
423 : : {
424 : 5051765 : StdLockGuard scoped_lock(m_cs);
425 [ + - ]: 5051765 : return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit);
426 : 5051765 : }
427 : :
428 : : // NOLINTNEXTLINE(misc-no-recursion)
429 : 5051765 : void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
430 : : {
431 : 5051765 : std::string str_prefixed = LogEscapeMessage(str);
432 : :
433 [ + + ]: 5051765 : if (m_buffering) {
434 : 20604 : {
435 : 20604 : BufferedLog buf{
436 : 20604 : .now = SystemClock::now(),
437 [ + - ]: 20604 : .mocktime = GetMockTime(),
438 : : .str = str_prefixed,
439 : : .threadname = util::ThreadGetInternalName(),
440 : : .source_loc = std::move(source_loc),
441 : : .category = category,
442 : : .level = level,
443 [ + - ]: 20604 : };
444 : 20604 : m_cur_buffer_memusage += MemUsage(buf);
445 [ + - ]: 20604 : m_msgs_before_open.push_back(std::move(buf));
446 : 0 : }
447 : :
448 [ + + ]: 23964 : while (m_cur_buffer_memusage > m_max_buffer_memusage) {
449 [ - + ]: 3360 : if (m_msgs_before_open.empty()) {
450 : 0 : m_cur_buffer_memusage = 0;
451 : 0 : break;
452 : : }
453 : 3360 : m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
454 : 3360 : m_msgs_before_open.pop_front();
455 : 3360 : ++m_buffer_lines_discarded;
456 : : }
457 : :
458 : 20604 : return;
459 : : }
460 : :
461 [ + - + - : 10062322 : FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime());
+ - ]
462 : 5031161 : bool ratelimit{false};
463 [ + + - + ]: 5031161 : if (should_ratelimit && m_limiter) {
464 [ # # ]: 0 : auto status{m_limiter->Consume(source_loc, str_prefixed)};
465 [ # # ]: 0 : if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
466 : : // NOLINTNEXTLINE(misc-no-recursion)
467 [ # # ]: 0 : 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 [ # # # # : 0 : source_loc.file_name(), source_loc.line(), source_loc.function_name(),
# # ]
473 [ # # ]: 0 : m_limiter->m_max_bytes,
474 : 0 : Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
475 [ # # ]: 0 : std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion
476 [ # # ]: 0 : } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
477 : 0 : 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 [ - + - - ]: 5031161 : if (m_limiter && m_limiter->SuppressionsActive()) {
484 [ # # ]: 0 : str_prefixed.insert(0, "[*] ");
485 : : }
486 : :
487 [ - + ]: 5031161 : if (m_print_to_console) {
488 : : // print to console
489 [ # # # # ]: 0 : fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
490 [ # # ]: 0 : fflush(stdout);
491 : : }
492 [ - + ]: 5031161 : for (const auto& cb : m_print_callbacks) {
493 [ # # ]: 0 : cb(str_prefixed);
494 : : }
495 [ + - + - ]: 5031161 : if (m_print_to_file && !ratelimit) {
496 [ - + ]: 5031161 : assert(m_fileout != nullptr);
497 : :
498 : : // reopen the log file, if requested
499 [ - + ]: 5031161 : if (m_reopen_file) {
500 [ # # ]: 0 : m_reopen_file = false;
501 [ # # ]: 0 : FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
502 [ # # ]: 0 : if (new_fileout) {
503 : 0 : setbuf(new_fileout, nullptr); // unbuffered
504 [ # # ]: 0 : fclose(m_fileout);
505 : 0 : m_fileout = new_fileout;
506 : : }
507 : : }
508 [ - + + - ]: 5031161 : FileWriteStr(str_prefixed, m_fileout);
509 : : }
510 : 5051765 : }
511 : :
512 : 0 : void BCLog::Logger::ShrinkDebugFile()
513 : : {
514 : : // Amount of debug.log to save at end when shrinking (must fit in memory)
515 : 0 : constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
516 : :
517 [ # # ]: 0 : assert(!m_file_path.empty());
518 : :
519 : : // Scroll debug.log if it's getting too big
520 : 0 : FILE* file = fsbridge::fopen(m_file_path, "r");
521 : :
522 : : // Special files (e.g. device nodes) may not have a size.
523 : 0 : size_t log_size = 0;
524 : 0 : try {
525 [ # # ]: 0 : log_size = fs::file_size(m_file_path);
526 [ - - ]: 0 : } 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 [ # # ]: 0 : if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
531 : : {
532 : : // Restart the file with some of the end
533 : 0 : std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
534 [ # # # # ]: 0 : if (fseek(file, -((long)vch.size()), SEEK_END)) {
535 [ # # ]: 0 : LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
536 [ # # ]: 0 : fclose(file);
537 : 0 : return;
538 : : }
539 [ # # # # ]: 0 : int nBytes = fread(vch.data(), 1, vch.size(), file);
540 [ # # ]: 0 : fclose(file);
541 : :
542 [ # # ]: 0 : file = fsbridge::fopen(m_file_path, "w");
543 [ # # ]: 0 : if (file)
544 : : {
545 [ # # ]: 0 : fwrite(vch.data(), 1, nBytes, file);
546 [ # # ]: 0 : fclose(file);
547 : : }
548 : 0 : }
549 [ # # ]: 0 : else if (file != nullptr)
550 : 0 : fclose(file);
551 : : }
552 : :
553 : 0 : void BCLog::LogRateLimiter::Reset()
554 : : {
555 [ # # ]: 0 : decltype(m_source_locations) source_locations;
556 : 0 : {
557 [ # # ]: 0 : StdLockGuard scoped_lock(m_mutex);
558 : 0 : source_locations.swap(m_source_locations);
559 : 0 : m_suppression_active = false;
560 : 0 : }
561 [ # # # # ]: 0 : for (const auto& [source_loc, stats] : source_locations) {
562 [ # # ]: 0 : if (stats.m_dropped_bytes == 0) continue;
563 [ # # # # : 0 : 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 : 0 : }
570 : :
571 : 0 : bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes)
572 : : {
573 [ # # ]: 0 : if (bytes > m_available_bytes) {
574 : 0 : m_dropped_bytes += bytes;
575 : 0 : m_available_bytes = 0;
576 : 0 : return false;
577 : : }
578 : :
579 : 0 : m_available_bytes -= bytes;
580 : 0 : return true;
581 : : }
582 : :
583 : 1572 : bool BCLog::Logger::SetLogLevel(std::string_view level_str)
584 : : {
585 : 1572 : const auto level = GetLogLevel(level_str);
586 [ + - + - ]: 1572 : if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
587 : 1572 : m_log_level = level.value();
588 : 1572 : return true;
589 : : }
590 : :
591 : 0 : bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str)
592 : : {
593 : 0 : BCLog::LogFlags flag;
594 [ # # ]: 0 : if (!GetLogCategory(flag, category_str)) return false;
595 : :
596 : 0 : const auto level = GetLogLevel(level_str);
597 [ # # # # ]: 0 : if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
598 : :
599 : 0 : StdLockGuard scoped_lock(m_cs);
600 [ # # ]: 0 : m_category_log_levels[flag] = level.value();
601 : 0 : return true;
602 : 0 : }
|
