Branch data Line data Source code
1 : : // Copyright (c) 2009-2010 Satoshi Nakamoto
2 : : // Copyright (c) 2009-2022 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 <util/fs.h>
8 : : #include <util/string.h>
9 : : #include <util/threadnames.h>
10 : : #include <util/time.h>
11 : :
12 : : #include <array>
13 : : #include <map>
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 : 223694 : 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 [ + + - + : 223694 : static BCLog::Logger* g_logger{new BCLog::Logger()};
+ - ]
37 : 223694 : return *g_logger;
38 : 0 : }
39 : :
40 : : bool fLogIPs = DEFAULT_LOGIPS;
41 : :
42 : 0 : static int FileWriteStr(const std::string &str, FILE *fp)
43 : : {
44 : 0 : return fwrite(str.data(), 1, str.size(), fp);
45 : : }
46 : :
47 : 2 : bool BCLog::Logger::StartLogging()
48 : : {
49 : 2 : StdLockGuard scoped_lock(m_cs);
50 : :
51 [ + - ]: 2 : assert(m_buffering);
52 [ + - ]: 2 : assert(m_fileout == nullptr);
53 : :
54 [ + - ]: 2 : if (m_print_to_file) {
55 [ # # ]: 0 : assert(!m_file_path.empty());
56 [ # # ]: 0 : m_fileout = fsbridge::fopen(m_file_path, "a");
57 [ # # ]: 0 : if (!m_fileout) {
58 : 0 : return false;
59 : : }
60 : :
61 : 0 : setbuf(m_fileout, nullptr); // unbuffered
62 : :
63 : : // Add newlines to the logfile to distinguish this execution from the
64 : : // last one.
65 [ # # # # ]: 0 : FileWriteStr("\n\n\n\n\n", m_fileout);
66 : 0 : }
67 : :
68 : : // dump buffered messages from before we opened the log
69 : 2 : m_buffering = false;
70 [ + + ]: 8 : while (!m_msgs_before_open.empty()) {
71 : 6 : const std::string& s = m_msgs_before_open.front();
72 : :
73 [ + - # # ]: 6 : if (m_print_to_file) FileWriteStr(s, m_fileout);
74 [ - + # # ]: 9 : if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
75 [ - + ]: 6 : for (const auto& cb : m_print_callbacks) {
76 [ # # ]: 0 : cb(s);
77 : 0 : }
78 : :
79 : 6 : m_msgs_before_open.pop_front();
80 : 6 : }
81 [ - + # # ]: 2 : if (m_print_to_console) fflush(stdout);
82 : :
83 : 2 : return true;
84 : 2 : }
85 : :
86 : 2 : void BCLog::Logger::DisconnectTestLogger()
87 : : {
88 : 2 : StdLockGuard scoped_lock(m_cs);
89 : 2 : m_buffering = true;
90 [ + - # # ]: 2 : if (m_fileout != nullptr) fclose(m_fileout);
91 : 2 : m_fileout = nullptr;
92 : 2 : m_print_callbacks.clear();
93 : 2 : }
94 : :
95 : 0 : void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
96 : : {
97 : 0 : m_categories |= flag;
98 : 0 : }
99 : :
100 : 0 : bool BCLog::Logger::EnableCategory(const std::string& str)
101 : : {
102 : 0 : BCLog::LogFlags flag;
103 [ # # ]: 0 : if (!GetLogCategory(flag, str)) return false;
104 : 0 : EnableCategory(flag);
105 : 0 : return true;
106 : 0 : }
107 : :
108 : 4 : void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
109 : : {
110 : 4 : m_categories &= ~flag;
111 : 4 : }
112 : :
113 : 4 : bool BCLog::Logger::DisableCategory(const std::string& str)
114 : : {
115 : 4 : BCLog::LogFlags flag;
116 [ - + ]: 4 : if (!GetLogCategory(flag, str)) return false;
117 : 4 : DisableCategory(flag);
118 : 4 : return true;
119 : 4 : }
120 : :
121 : 216452 : bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
122 : : {
123 : 216452 : return (m_categories.load(std::memory_order_relaxed) & category) != 0;
124 : : }
125 : :
126 : 216228 : 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 [ - + ]: 216228 : if (level >= BCLog::Level::Info) return true;
131 : :
132 [ - + ]: 216228 : if (!WillLogCategory(category)) return false;
133 : :
134 : 0 : StdLockGuard scoped_lock(m_cs);
135 [ # # ]: 0 : const auto it{m_category_log_levels.find(category)};
136 [ # # # # ]: 0 : return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
137 : 216228 : }
138 : :
139 : 0 : bool BCLog::Logger::DefaultShrinkDebugFile() const
140 : : {
141 : 0 : return m_categories == BCLog::NONE;
142 : : }
143 : :
144 [ + - # # ]: 3 : static const std::map<std::string, BCLog::LogFlags> LOG_CATEGORIES_BY_STR{
145 [ + - ]: 3 : {"0", BCLog::NONE},
146 [ + - ]: 3 : {"", BCLog::NONE},
147 [ + - ]: 3 : {"net", BCLog::NET},
148 [ + - ]: 3 : {"tor", BCLog::TOR},
149 [ + - ]: 3 : {"mempool", BCLog::MEMPOOL},
150 [ + - ]: 3 : {"http", BCLog::HTTP},
151 [ + - ]: 3 : {"bench", BCLog::BENCH},
152 [ + - ]: 3 : {"zmq", BCLog::ZMQ},
153 [ + - ]: 3 : {"walletdb", BCLog::WALLETDB},
154 [ + - ]: 3 : {"rpc", BCLog::RPC},
155 [ + - ]: 3 : {"estimatefee", BCLog::ESTIMATEFEE},
156 [ + - ]: 3 : {"addrman", BCLog::ADDRMAN},
157 [ + - ]: 3 : {"selectcoins", BCLog::SELECTCOINS},
158 [ + - ]: 3 : {"reindex", BCLog::REINDEX},
159 [ + - ]: 3 : {"cmpctblock", BCLog::CMPCTBLOCK},
160 [ + - ]: 3 : {"rand", BCLog::RAND},
161 [ + - ]: 3 : {"prune", BCLog::PRUNE},
162 [ + - ]: 3 : {"proxy", BCLog::PROXY},
163 [ + - ]: 3 : {"mempoolrej", BCLog::MEMPOOLREJ},
164 [ + - ]: 3 : {"libevent", BCLog::LIBEVENT},
165 [ + - ]: 3 : {"coindb", BCLog::COINDB},
166 [ + - ]: 3 : {"qt", BCLog::QT},
167 [ + - ]: 3 : {"leveldb", BCLog::LEVELDB},
168 [ + - ]: 3 : {"validation", BCLog::VALIDATION},
169 [ + - ]: 3 : {"i2p", BCLog::I2P},
170 [ + - ]: 3 : {"ipc", BCLog::IPC},
171 : : #ifdef DEBUG_LOCKCONTENTION
172 : : {"lock", BCLog::LOCK},
173 : : #endif
174 [ + - ]: 3 : {"blockstorage", BCLog::BLOCKSTORAGE},
175 [ + - ]: 3 : {"txreconciliation", BCLog::TXRECONCILIATION},
176 [ + - ]: 3 : {"scan", BCLog::SCAN},
177 [ + - ]: 3 : {"txpackages", BCLog::TXPACKAGES},
178 [ + - ]: 3 : {"1", BCLog::ALL},
179 [ + - ]: 3 : {"all", BCLog::ALL},
180 : : };
181 : :
182 : 3 : static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
183 : : // Swap keys and values from LOG_CATEGORIES_BY_STR.
184 : 6 : [](const std::map<std::string, BCLog::LogFlags>& in) {
185 : 3 : std::unordered_map<BCLog::LogFlags, std::string> out;
186 [ + + ]: 99 : for (const auto& [k, v] : in) {
187 [ + + + ]: 96 : switch (v) {
188 [ + - ]: 6 : case BCLog::NONE: out.emplace(BCLog::NONE, ""); break;
189 [ + - ]: 6 : case BCLog::ALL: out.emplace(BCLog::ALL, "all"); break;
190 [ + - ]: 84 : default: out.emplace(v, k);
191 : 84 : }
192 : 96 : }
193 : 3 : return out;
194 [ + - ]: 6 : }(LOG_CATEGORIES_BY_STR)
195 : : };
196 : :
197 : 4 : bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
198 : : {
199 [ - + ]: 4 : if (str.empty()) {
200 : 0 : flag = BCLog::ALL;
201 : 0 : return true;
202 : : }
203 : 4 : auto it = LOG_CATEGORIES_BY_STR.find(str);
204 [ + - ]: 4 : if (it != LOG_CATEGORIES_BY_STR.end()) {
205 : 4 : flag = it->second;
206 : 4 : return true;
207 : : }
208 : 0 : return false;
209 : 4 : }
210 : :
211 : 8 : std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
212 : : {
213 [ + + - - : 8 : switch (level) {
+ - ]
214 : : case BCLog::Level::Trace:
215 [ - + ]: 2 : return "trace";
216 : : case BCLog::Level::Debug:
217 [ + - ]: 4 : return "debug";
218 : : case BCLog::Level::Info:
219 [ + - ]: 2 : return "info";
220 : : case BCLog::Level::Warning:
221 [ # # ]: 0 : return "warning";
222 : : case BCLog::Level::Error:
223 [ # # ]: 0 : return "error";
224 : : }
225 : 0 : assert(false);
226 : 8 : }
227 : :
228 : 0 : std::string LogCategoryToStr(BCLog::LogFlags category)
229 : : {
230 : 0 : auto it = LOG_CATEGORIES_BY_FLAG.find(category);
231 [ # # ]: 0 : assert(it != LOG_CATEGORIES_BY_FLAG.end());
232 : 0 : return it->second;
233 : 0 : }
234 : :
235 : 2 : static std::optional<BCLog::Level> GetLogLevel(const std::string& level_str)
236 : : {
237 [ + - ]: 2 : if (level_str == "trace") {
238 : 2 : return BCLog::Level::Trace;
239 [ # # ]: 0 : } else if (level_str == "debug") {
240 : 0 : return BCLog::Level::Debug;
241 [ # # ]: 0 : } else if (level_str == "info") {
242 : 0 : return BCLog::Level::Info;
243 [ # # ]: 0 : } else if (level_str == "warning") {
244 : 0 : return BCLog::Level::Warning;
245 [ # # ]: 0 : } else if (level_str == "error") {
246 : 0 : return BCLog::Level::Error;
247 : : } else {
248 : 0 : return std::nullopt;
249 : : }
250 : 2 : }
251 : :
252 : 8 : std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
253 : : {
254 : 8 : std::vector<LogCategory> ret;
255 [ + + ]: 264 : for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
256 [ + + + + ]: 256 : if (flag != BCLog::NONE && flag != BCLog::ALL) {
257 [ - + - + : 448 : ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
- + - + ]
258 : 224 : }
259 : 256 : }
260 : 8 : return ret;
261 [ + - ]: 8 : }
262 : :
263 : : /** Log severity levels that can be selected by the user. */
264 : 2 : static constexpr std::array<BCLog::Level, 3> LogLevelsList()
265 : : {
266 : 2 : return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
267 : : }
268 : :
269 : 2 : std::string BCLog::Logger::LogLevelsString() const
270 : : {
271 : 2 : const auto& levels = LogLevelsList();
272 [ + - - + ]: 8 : return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
273 : 2 : }
274 : :
275 : 6 : std::string BCLog::Logger::LogTimestampStr(const std::string& str)
276 : : {
277 : 6 : std::string strStamped;
278 : :
279 [ - + ]: 6 : if (!m_log_timestamps)
280 [ # # ]: 0 : return str;
281 : :
282 [ - + ]: 6 : if (m_started_new_line) {
283 : 6 : const auto now{SystemClock::now()};
284 [ + - ]: 6 : const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
285 [ + - + - ]: 6 : strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
286 [ + + - + ]: 6 : if (m_log_time_micros && !strStamped.empty()) {
287 : 4 : strStamped.pop_back();
288 [ + - + - : 4 : strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
+ - - + ]
289 : 4 : }
290 [ + - ]: 6 : std::chrono::seconds mocktime = GetMockTime();
291 [ + - + - : 6 : if (mocktime > 0s) {
+ - ]
292 [ # # # # : 0 : strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
# # # # #
# ]
293 : 0 : }
294 [ + - + - ]: 6 : strStamped += ' ' + str;
295 : 6 : } else
296 [ # # ]: 0 : strStamped = str;
297 : :
298 : 6 : return strStamped;
299 : 6 : }
300 : :
301 : : namespace BCLog {
302 : : /** Belts and suspenders: make sure outgoing log messages don't contain
303 : : * potentially suspicious characters, such as terminal control codes.
304 : : *
305 : : * This escapes control characters except newline ('\n') in C syntax.
306 : : * It escapes instead of removes them to still allow for troubleshooting
307 : : * issues where they accidentally end up in strings.
308 : : */
309 : 6 : std::string LogEscapeMessage(const std::string& str) {
310 : 6 : std::string ret;
311 [ + + ]: 454 : for (char ch_in : str) {
312 : 448 : uint8_t ch = (uint8_t)ch_in;
313 [ + + - + ]: 448 : if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
314 [ + - ]: 448 : ret += ch_in;
315 : 448 : } else {
316 [ # # # # ]: 0 : ret += strprintf("\\x%02x", ch);
317 : : }
318 : 448 : }
319 : 6 : return ret;
320 [ + - ]: 6 : }
321 : : } // namespace BCLog
322 : :
323 : 6 : std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
324 : : {
325 [ + - ]: 6 : if (category == LogFlags::NONE) category = LogFlags::ALL;
326 : :
327 [ - + ]: 6 : const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
328 : :
329 : : // If there is no category, Info is implied
330 [ + - - + ]: 6 : if (!has_category && level == Level::Info) return {};
331 : :
332 [ # # ]: 0 : std::string s{"["};
333 [ # # ]: 0 : if (has_category) {
334 [ # # # # ]: 0 : s += LogCategoryToStr(category);
335 : 0 : }
336 : :
337 [ # # # # : 0 : if (m_always_print_category_level || !has_category || level != Level::Debug) {
# # ]
338 : : // If there is a category, Debug is implied, so don't add the level
339 : :
340 : : // Only add separator if we have a category
341 [ # # # # ]: 0 : if (has_category) s += ":";
342 [ # # # # ]: 0 : s += Logger::LogLevelToStr(level);
343 : 0 : }
344 : :
345 [ # # ]: 0 : s += "] ";
346 : 0 : return s;
347 [ # # ]: 6 : }
348 : :
349 : 6 : 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)
350 : : {
351 : 6 : StdLockGuard scoped_lock(m_cs);
352 [ + - ]: 6 : std::string str_prefixed = LogEscapeMessage(str);
353 : :
354 [ - + ]: 6 : if (m_started_new_line) {
355 [ + - + - ]: 6 : str_prefixed.insert(0, GetLogPrefix(category, level));
356 : 6 : }
357 : :
358 [ + + - + ]: 6 : if (m_log_sourcelocations && m_started_new_line) {
359 [ + - + - : 4 : str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
+ - + - +
- + - + -
+ - + - ]
360 : 4 : }
361 : :
362 [ + + - + ]: 6 : if (m_log_threadnames && m_started_new_line) {
363 [ + - ]: 4 : const auto& threadname = util::ThreadGetInternalName();
364 [ + - # # : 4 : str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
+ - + - +
- + - + -
+ - # # #
# ]
365 : 4 : }
366 : :
367 [ + - ]: 6 : str_prefixed = LogTimestampStr(str_prefixed);
368 : :
369 [ - + ]: 6 : m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
370 : :
371 [ + - ]: 6 : if (m_buffering) {
372 : : // buffer if we haven't started logging yet
373 [ + - ]: 6 : m_msgs_before_open.push_back(str_prefixed);
374 : 6 : return;
375 : : }
376 : :
377 [ # # ]: 0 : if (m_print_to_console) {
378 : : // print to console
379 [ # # ]: 0 : fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
380 [ # # ]: 0 : fflush(stdout);
381 : 0 : }
382 [ # # ]: 0 : for (const auto& cb : m_print_callbacks) {
383 [ # # ]: 0 : cb(str_prefixed);
384 : 0 : }
385 [ # # ]: 0 : if (m_print_to_file) {
386 [ # # ]: 0 : assert(m_fileout != nullptr);
387 : :
388 : : // reopen the log file, if requested
389 [ # # ]: 0 : if (m_reopen_file) {
390 : 0 : m_reopen_file = false;
391 [ # # ]: 0 : FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
392 [ # # ]: 0 : if (new_fileout) {
393 : 0 : setbuf(new_fileout, nullptr); // unbuffered
394 [ # # ]: 0 : fclose(m_fileout);
395 : 0 : m_fileout = new_fileout;
396 : 0 : }
397 : 0 : }
398 [ # # ]: 0 : FileWriteStr(str_prefixed, m_fileout);
399 : 0 : }
400 [ - + ]: 6 : }
401 : :
402 : 0 : void BCLog::Logger::ShrinkDebugFile()
403 : : {
404 : : // Amount of debug.log to save at end when shrinking (must fit in memory)
405 : 0 : constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
406 : :
407 [ # # ]: 0 : assert(!m_file_path.empty());
408 : :
409 : : // Scroll debug.log if it's getting too big
410 : 0 : FILE* file = fsbridge::fopen(m_file_path, "r");
411 : :
412 : : // Special files (e.g. device nodes) may not have a size.
413 : 0 : size_t log_size = 0;
414 : : try {
415 [ # # ]: 0 : log_size = fs::file_size(m_file_path);
416 [ # # ]: 0 : } catch (const fs::filesystem_error&) {}
417 : :
418 : : // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
419 : : // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
420 [ # # # # ]: 0 : if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
421 : : {
422 : : // Restart the file with some of the end
423 [ # # ]: 0 : std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
424 [ # # # # ]: 0 : if (fseek(file, -((long)vch.size()), SEEK_END)) {
425 [ # # # # : 0 : LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
# # ]
426 [ # # ]: 0 : fclose(file);
427 : 0 : return;
428 : : }
429 [ # # ]: 0 : int nBytes = fread(vch.data(), 1, vch.size(), file);
430 [ # # ]: 0 : fclose(file);
431 : :
432 [ # # ]: 0 : file = fsbridge::fopen(m_file_path, "w");
433 [ # # ]: 0 : if (file)
434 : : {
435 [ # # ]: 0 : fwrite(vch.data(), 1, nBytes, file);
436 [ # # ]: 0 : fclose(file);
437 : 0 : }
438 [ # # ]: 0 : }
439 [ # # ]: 0 : else if (file != nullptr)
440 : 0 : fclose(file);
441 [ # # ]: 0 : }
442 : :
443 : 2 : bool BCLog::Logger::SetLogLevel(const std::string& level_str)
444 : : {
445 : 2 : const auto level = GetLogLevel(level_str);
446 [ + - - + ]: 2 : if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
447 : 2 : m_log_level = level.value();
448 : 2 : return true;
449 : 2 : }
450 : :
451 : 0 : bool BCLog::Logger::SetCategoryLogLevel(const std::string& category_str, const std::string& level_str)
452 : : {
453 : 0 : BCLog::LogFlags flag;
454 [ # # ]: 0 : if (!GetLogCategory(flag, category_str)) return false;
455 : :
456 : 0 : const auto level = GetLogLevel(level_str);
457 [ # # # # ]: 0 : if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
458 : :
459 : 0 : StdLockGuard scoped_lock(m_cs);
460 [ # # # # ]: 0 : m_category_log_levels[flag] = level.value();
461 : 0 : return true;
462 : 0 : }
|
