Branch data Line data Source code
# 1 : : // Copyright (c) 2009-2010 Satoshi Nakamoto
# 2 : : // Copyright (c) 2009-2021 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 <fs.h>
# 7 : : #include <logging.h>
# 8 : : #include <util/threadnames.h>
# 9 : : #include <util/string.h>
# 10 : : #include <util/time.h>
# 11 : :
# 12 : : #include <algorithm>
# 13 : : #include <array>
# 14 : : #include <mutex>
# 15 : :
# 16 : : const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
# 17 : :
# 18 : : BCLog::Logger& LogInstance()
# 19 : 45669995 : {
# 20 : : /**
# 21 : : * NOTE: the logger instances is leaked on exit. This is ugly, but will be
# 22 : : * cleaned up by the OS/libc. Defining a logger as a global object doesn't work
# 23 : : * since the order of destruction of static/global objects is undefined.
# 24 : : * Consider if the logger gets destroyed, and then some later destructor calls
# 25 : : * LogPrintf, maybe indirectly, and you get a core dump at shutdown trying to
# 26 : : * access the logger. When the shutdown sequence is fully audited and tested,
# 27 : : * explicit destruction of these objects can be implemented by changing this
# 28 : : * from a raw pointer to a std::unique_ptr.
# 29 : : * Since the ~Logger() destructor is never called, the Logger class and all
# 30 : : * its subclasses must have implicitly-defined destructors.
# 31 : : *
# 32 : : * This method of initialization was originally introduced in
# 33 : : * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c.
# 34 : : */
# 35 : 45669995 : static BCLog::Logger* g_logger{new BCLog::Logger()};
# 36 : 45669995 : return *g_logger;
# 37 : 45669995 : }
# 38 : :
# 39 : : bool fLogIPs = DEFAULT_LOGIPS;
# 40 : :
# 41 : : static int FileWriteStr(const std::string &str, FILE *fp)
# 42 : 4460462 : {
# 43 : 4460462 : return fwrite(str.data(), 1, str.size(), fp);
# 44 : 4460462 : }
# 45 : :
# 46 : : bool BCLog::Logger::StartLogging()
# 47 : 1669 : {
# 48 : 1669 : StdLockGuard scoped_lock(m_cs);
# 49 : :
# 50 : 1669 : assert(m_buffering);
# 51 : 0 : assert(m_fileout == nullptr);
# 52 : :
# 53 [ + + ]: 1669 : if (m_print_to_file) {
# 54 : 1668 : assert(!m_file_path.empty());
# 55 : 0 : m_fileout = fsbridge::fopen(m_file_path, "a");
# 56 [ + + ]: 1668 : if (!m_fileout) {
# 57 : 2 : return false;
# 58 : 2 : }
# 59 : :
# 60 : 1666 : setbuf(m_fileout, nullptr); // unbuffered
# 61 : :
# 62 : : // Add newlines to the logfile to distinguish this execution from the
# 63 : : // last one.
# 64 : 1666 : FileWriteStr("\n\n\n\n\n", m_fileout);
# 65 : 1666 : }
# 66 : :
# 67 : : // dump buffered messages from before we opened the log
# 68 : 1667 : m_buffering = false;
# 69 [ + + ]: 12234 : while (!m_msgs_before_open.empty()) {
# 70 : 10567 : const std::string& s = m_msgs_before_open.front();
# 71 : :
# 72 [ + + ]: 10567 : if (m_print_to_file) FileWriteStr(s, m_fileout);
# 73 [ - + ]: 10567 : if (m_print_to_console) fwrite(s.data(), 1, s.size(), stdout);
# 74 [ + + ]: 10567 : for (const auto& cb : m_print_callbacks) {
# 75 : 4802 : cb(s);
# 76 : 4802 : }
# 77 : :
# 78 : 10567 : m_msgs_before_open.pop_front();
# 79 : 10567 : }
# 80 [ - + ]: 1667 : if (m_print_to_console) fflush(stdout);
# 81 : :
# 82 : 1667 : return true;
# 83 : 1669 : }
# 84 : :
# 85 : : void BCLog::Logger::DisconnectTestLogger()
# 86 : 854 : {
# 87 : 854 : StdLockGuard scoped_lock(m_cs);
# 88 : 854 : m_buffering = true;
# 89 [ + - ]: 854 : if (m_fileout != nullptr) fclose(m_fileout);
# 90 : 854 : m_fileout = nullptr;
# 91 : 854 : m_print_callbacks.clear();
# 92 : 854 : }
# 93 : :
# 94 : : void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
# 95 : 1682 : {
# 96 : 1682 : m_categories |= flag;
# 97 : 1682 : }
# 98 : :
# 99 : : bool BCLog::Logger::EnableCategory(const std::string& str)
# 100 : 1680 : {
# 101 : 1680 : BCLog::LogFlags flag;
# 102 [ - + ]: 1680 : if (!GetLogCategory(flag, str)) return false;
# 103 : 1680 : EnableCategory(flag);
# 104 : 1680 : return true;
# 105 : 1680 : }
# 106 : :
# 107 : : void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
# 108 : 3379 : {
# 109 : 3379 : m_categories &= ~flag;
# 110 : 3379 : }
# 111 : :
# 112 : : bool BCLog::Logger::DisableCategory(const std::string& str)
# 113 : 3379 : {
# 114 : 3379 : BCLog::LogFlags flag;
# 115 [ - + ]: 3379 : if (!GetLogCategory(flag, str)) return false;
# 116 : 3379 : DisableCategory(flag);
# 117 : 3379 : return true;
# 118 : 3379 : }
# 119 : :
# 120 : : bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
# 121 : 36784023 : {
# 122 : 36784023 : return (m_categories.load(std::memory_order_relaxed) & category) != 0;
# 123 : 36784023 : }
# 124 : :
# 125 : : bool BCLog::Logger::DefaultShrinkDebugFile() const
# 126 : 814 : {
# 127 : 814 : return m_categories == BCLog::NONE;
# 128 : 814 : }
# 129 : :
# 130 : : struct CLogCategoryDesc {
# 131 : : BCLog::LogFlags flag;
# 132 : : std::string category;
# 133 : : };
# 134 : :
# 135 : : const CLogCategoryDesc LogCategories[] =
# 136 : : {
# 137 : : {BCLog::NONE, "0"},
# 138 : : {BCLog::NONE, "none"},
# 139 : : {BCLog::NET, "net"},
# 140 : : {BCLog::TOR, "tor"},
# 141 : : {BCLog::MEMPOOL, "mempool"},
# 142 : : {BCLog::HTTP, "http"},
# 143 : : {BCLog::BENCH, "bench"},
# 144 : : {BCLog::ZMQ, "zmq"},
# 145 : : {BCLog::WALLETDB, "walletdb"},
# 146 : : {BCLog::RPC, "rpc"},
# 147 : : {BCLog::ESTIMATEFEE, "estimatefee"},
# 148 : : {BCLog::ADDRMAN, "addrman"},
# 149 : : {BCLog::SELECTCOINS, "selectcoins"},
# 150 : : {BCLog::REINDEX, "reindex"},
# 151 : : {BCLog::CMPCTBLOCK, "cmpctblock"},
# 152 : : {BCLog::RAND, "rand"},
# 153 : : {BCLog::PRUNE, "prune"},
# 154 : : {BCLog::PROXY, "proxy"},
# 155 : : {BCLog::MEMPOOLREJ, "mempoolrej"},
# 156 : : {BCLog::LIBEVENT, "libevent"},
# 157 : : {BCLog::COINDB, "coindb"},
# 158 : : {BCLog::QT, "qt"},
# 159 : : {BCLog::LEVELDB, "leveldb"},
# 160 : : {BCLog::VALIDATION, "validation"},
# 161 : : {BCLog::I2P, "i2p"},
# 162 : : {BCLog::IPC, "ipc"},
# 163 : : #ifdef DEBUG_LOCKCONTENTION
# 164 : : {BCLog::LOCK, "lock"},
# 165 : : #endif
# 166 : : {BCLog::UTIL, "util"},
# 167 : : {BCLog::BLOCKSTORE, "blockstorage"},
# 168 : : {BCLog::HEADERSSYNC, "headerssync"},
# 169 : : {BCLog::ALL, "1"},
# 170 : : {BCLog::ALL, "all"},
# 171 : : };
# 172 : :
# 173 : : bool GetLogCategory(BCLog::LogFlags& flag, const std::string& str)
# 174 : 5115 : {
# 175 [ + + ]: 5115 : if (str.empty()) {
# 176 : 1679 : flag = BCLog::ALL;
# 177 : 1679 : return true;
# 178 : 1679 : }
# 179 [ + - ]: 73705 : for (const CLogCategoryDesc& category_desc : LogCategories) {
# 180 [ + + ]: 73705 : if (category_desc.category == str) {
# 181 : 3436 : flag = category_desc.flag;
# 182 : 3436 : return true;
# 183 : 3436 : }
# 184 : 73705 : }
# 185 : 0 : return false;
# 186 : 3436 : }
# 187 : :
# 188 : : std::string LogLevelToStr(BCLog::Level level)
# 189 : 1091 : {
# 190 [ - + ]: 1091 : switch (level) {
# 191 [ - + ]: 0 : case BCLog::Level::None:
# 192 : 0 : return "none";
# 193 [ + + ]: 448 : case BCLog::Level::Debug:
# 194 : 448 : return "debug";
# 195 [ + + ]: 2 : case BCLog::Level::Info:
# 196 : 2 : return "info";
# 197 [ + + ]: 2 : case BCLog::Level::Warning:
# 198 : 2 : return "warning";
# 199 [ + + ]: 639 : case BCLog::Level::Error:
# 200 : 639 : return "error";
# 201 : 1091 : }
# 202 : 0 : assert(false);
# 203 : 0 : }
# 204 : :
# 205 : : std::string LogCategoryToStr(BCLog::LogFlags category)
# 206 : 4112152 : {
# 207 : : // Each log category string representation should sync with LogCategories
# 208 [ - + ]: 4112152 : switch (category) {
# 209 [ - + ]: 0 : case BCLog::LogFlags::NONE:
# 210 : 0 : return "none";
# 211 [ + + ]: 502737 : case BCLog::LogFlags::NET:
# 212 : 502737 : return "net";
# 213 [ + + ]: 2 : case BCLog::LogFlags::TOR:
# 214 : 2 : return "tor";
# 215 [ + + ]: 127147 : case BCLog::LogFlags::MEMPOOL:
# 216 : 127147 : return "mempool";
# 217 [ + + ]: 147968 : case BCLog::LogFlags::HTTP:
# 218 : 147968 : return "http";
# 219 [ + + ]: 1263619 : case BCLog::LogFlags::BENCH:
# 220 : 1263619 : return "bench";
# 221 [ + + ]: 2 : case BCLog::LogFlags::ZMQ:
# 222 : 2 : return "zmq";
# 223 [ + + ]: 6037 : case BCLog::LogFlags::WALLETDB:
# 224 : 6037 : return "walletdb";
# 225 [ + + ]: 139276 : case BCLog::LogFlags::RPC:
# 226 : 139276 : return "rpc";
# 227 [ + + ]: 110983 : case BCLog::LogFlags::ESTIMATEFEE:
# 228 : 110983 : return "estimatefee";
# 229 [ + + ]: 51335 : case BCLog::LogFlags::ADDRMAN:
# 230 : 51335 : return "addrman";
# 231 [ + + ]: 3344 : case BCLog::LogFlags::SELECTCOINS:
# 232 : 3344 : return "selectcoins";
# 233 [ + + ]: 144 : case BCLog::LogFlags::REINDEX:
# 234 : 144 : return "reindex";
# 235 [ + + ]: 25267 : case BCLog::LogFlags::CMPCTBLOCK:
# 236 : 25267 : return "cmpctblock";
# 237 [ + + ]: 84 : case BCLog::LogFlags::RAND:
# 238 : 84 : return "rand";
# 239 [ + + ]: 34 : case BCLog::LogFlags::PRUNE:
# 240 : 34 : return "prune";
# 241 [ + + ]: 6 : case BCLog::LogFlags::PROXY:
# 242 : 6 : return "proxy";
# 243 [ + + ]: 330 : case BCLog::LogFlags::MEMPOOLREJ:
# 244 : 330 : return "mempoolrej";
# 245 [ + + ]: 2 : case BCLog::LogFlags::LIBEVENT:
# 246 : 2 : return "libevent";
# 247 [ + + ]: 4728 : case BCLog::LogFlags::COINDB:
# 248 : 4728 : return "coindb";
# 249 [ + + ]: 2 : case BCLog::LogFlags::QT:
# 250 : 2 : return "qt";
# 251 [ + + ]: 2 : case BCLog::LogFlags::LEVELDB:
# 252 : 2 : return "leveldb";
# 253 [ + + ]: 614570 : case BCLog::LogFlags::VALIDATION:
# 254 : 614570 : return "validation";
# 255 [ + + ]: 20 : case BCLog::LogFlags::I2P:
# 256 : 20 : return "i2p";
# 257 [ + + ]: 2 : case BCLog::LogFlags::IPC:
# 258 : 2 : return "ipc";
# 259 : 0 : #ifdef DEBUG_LOCKCONTENTION
# 260 [ + + ]: 1114456 : case BCLog::LogFlags::LOCK:
# 261 : 1114456 : return "lock";
# 262 : 0 : #endif
# 263 [ + + ]: 2 : case BCLog::LogFlags::UTIL:
# 264 : 2 : return "util";
# 265 [ + + ]: 15 : case BCLog::LogFlags::BLOCKSTORE:
# 266 : 15 : return "blockstorage";
# 267 [ + + ]: 38 : case BCLog::LogFlags::HEADERSSYNC:
# 268 : 38 : return "headerssync";
# 269 [ - + ]: 0 : case BCLog::LogFlags::ALL:
# 270 : 0 : return "all";
# 271 : 4112152 : }
# 272 : 0 : assert(false);
# 273 : 0 : }
# 274 : :
# 275 : : std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
# 276 : 3362 : {
# 277 : : // Sort log categories by alphabetical order.
# 278 : 3362 : std::array<CLogCategoryDesc, std::size(LogCategories)> categories;
# 279 : 3362 : std::copy(std::begin(LogCategories), std::end(LogCategories), categories.begin());
# 280 : 578264 : std::sort(categories.begin(), categories.end(), [](auto a, auto b) { return a.category < b.category; });
# 281 : :
# 282 : 3362 : std::vector<LogCategory> ret;
# 283 [ + + ]: 107584 : for (const CLogCategoryDesc& category_desc : categories) {
# 284 [ + + ][ + + ]: 107584 : if (category_desc.flag == BCLog::NONE || category_desc.flag == BCLog::ALL) continue;
# 285 : 94136 : LogCategory catActive;
# 286 : 94136 : catActive.category = category_desc.category;
# 287 : 94136 : catActive.active = WillLogCategory(category_desc.flag);
# 288 : 94136 : ret.push_back(catActive);
# 289 : 94136 : }
# 290 : 3362 : return ret;
# 291 : 3362 : }
# 292 : :
# 293 : : std::string BCLog::Logger::LogTimestampStr(const std::string& str)
# 294 : 4480673 : {
# 295 : 4480673 : std::string strStamped;
# 296 : :
# 297 [ + + ]: 4480673 : if (!m_log_timestamps)
# 298 : 84 : return str;
# 299 : :
# 300 [ + + ]: 4480589 : if (m_started_new_line) {
# 301 : 4477901 : int64_t nTimeMicros = GetTimeMicros();
# 302 : 4477901 : strStamped = FormatISO8601DateTime(nTimeMicros/1000000);
# 303 [ + + ]: 4477901 : if (m_log_time_micros) {
# 304 : 4456105 : strStamped.pop_back();
# 305 : 4456105 : strStamped += strprintf(".%06dZ", nTimeMicros%1000000);
# 306 : 4456105 : }
# 307 : 4477901 : std::chrono::seconds mocktime = GetMockTime();
# 308 [ + + ]: 4477901 : if (mocktime > 0s) {
# 309 : 433374 : strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
# 310 : 433374 : }
# 311 : 4477901 : strStamped += ' ' + str;
# 312 : 4477901 : } else
# 313 : 2688 : strStamped = str;
# 314 : :
# 315 : 4480589 : return strStamped;
# 316 : 4480673 : }
# 317 : :
# 318 : : namespace BCLog {
# 319 : : /** Belts and suspenders: make sure outgoing log messages don't contain
# 320 : : * potentially suspicious characters, such as terminal control codes.
# 321 : : *
# 322 : : * This escapes control characters except newline ('\n') in C syntax.
# 323 : : * It escapes instead of removes them to still allow for troubleshooting
# 324 : : * issues where they accidentally end up in strings.
# 325 : : */
# 326 : 4480677 : std::string LogEscapeMessage(const std::string& str) {
# 327 : 4480677 : std::string ret;
# 328 [ + + ]: 345221006 : for (char ch_in : str) {
# 329 : 345221006 : uint8_t ch = (uint8_t)ch_in;
# 330 [ + + ][ + + ]: 345221006 : if ((ch >= 32 || ch == '\n') && ch != '\x7f') {
# [ + + ]
# 331 : 345219421 : ret += ch_in;
# 332 : 345219421 : } else {
# 333 : 1585 : ret += strprintf("\\x%02x", ch);
# 334 : 1585 : }
# 335 : 345221006 : }
# 336 : 4480677 : return ret;
# 337 : 4480677 : }
# 338 : : } // namespace BCLog
# 339 : :
# 340 : : void BCLog::Logger::LogPrintStr(const std::string& str, const std::string& logging_function, const std::string& source_file, const int source_line, const BCLog::LogFlags category, const BCLog::Level level)
# 341 : 4478995 : {
# 342 : 4478995 : StdLockGuard scoped_lock(m_cs);
# 343 : 4478995 : std::string str_prefixed = LogEscapeMessage(str);
# 344 : :
# 345 [ + + ][ + + ]: 4478995 : if ((category != LogFlags::NONE || level != Level::None) && m_started_new_line) {
# [ + + ]
# 346 : 4112154 : std::string s{"["};
# 347 : :
# 348 [ + + ]: 4112154 : if (category != LogFlags::NONE) {
# 349 : 4112152 : s += LogCategoryToStr(category);
# 350 : 4112152 : }
# 351 : :
# 352 [ + + ][ + + ]: 4112154 : if (category != LogFlags::NONE && level != Level::None) {
# 353 : : // Only add separator if both flag and level are not NONE
# 354 : 1089 : s += ":";
# 355 : 1089 : }
# 356 : :
# 357 [ + + ]: 4112154 : if (level != Level::None) {
# 358 : 1091 : s += LogLevelToStr(level);
# 359 : 1091 : }
# 360 : :
# 361 : 4112154 : s += "] ";
# 362 : 4112154 : str_prefixed.insert(0, s);
# 363 : 4112154 : }
# 364 : :
# 365 [ + + ][ + + ]: 4478995 : if (m_log_sourcelocations && m_started_new_line) {
# 366 : 4456115 : str_prefixed.insert(0, "[" + RemovePrefix(source_file, "./") + ":" + ToString(source_line) + "] [" + logging_function + "] ");
# 367 : 4456115 : }
# 368 : :
# 369 [ - + ][ # # ]: 4478995 : if (m_log_threadnames && m_started_new_line) {
# 370 : 0 : const auto& threadname = util::ThreadGetInternalName();
# 371 [ # # ]: 0 : str_prefixed.insert(0, "[" + (threadname.empty() ? "unknown" : threadname) + "] ");
# 372 : 0 : }
# 373 : :
# 374 : 4478995 : str_prefixed = LogTimestampStr(str_prefixed);
# 375 : :
# 376 [ + + ][ + + ]: 4480673 : m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
# 377 : :
# 378 [ + + ]: 4478995 : if (m_buffering) {
# 379 : : // buffer if we haven't started logging yet
# 380 : 32437 : m_msgs_before_open.push_back(str_prefixed);
# 381 : 32437 : return;
# 382 : 32437 : }
# 383 : :
# 384 [ - + ]: 4446558 : if (m_print_to_console) {
# 385 : : // print to console
# 386 : 0 : fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
# 387 : 0 : fflush(stdout);
# 388 : 0 : }
# 389 [ + + ]: 4446558 : for (const auto& cb : m_print_callbacks) {
# 390 : 786365 : cb(str_prefixed);
# 391 : 786365 : }
# 392 [ + + ]: 4448236 : if (m_print_to_file) {
# 393 : 4448236 : assert(m_fileout != nullptr);
# 394 : :
# 395 : : // reopen the log file, if requested
# 396 [ + + ]: 4448236 : if (m_reopen_file) {
# 397 : 6 : m_reopen_file = false;
# 398 : 6 : FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
# 399 [ + - ]: 6 : if (new_fileout) {
# 400 : 6 : setbuf(new_fileout, nullptr); // unbuffered
# 401 : 6 : fclose(m_fileout);
# 402 : 6 : m_fileout = new_fileout;
# 403 : 6 : }
# 404 : 6 : }
# 405 : 4448236 : FileWriteStr(str_prefixed, m_fileout);
# 406 : 4448236 : }
# 407 : 4446558 : }
# 408 : :
# 409 : : void BCLog::Logger::ShrinkDebugFile()
# 410 : 0 : {
# 411 : : // Amount of debug.log to save at end when shrinking (must fit in memory)
# 412 : 0 : constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000;
# 413 : :
# 414 : 0 : assert(!m_file_path.empty());
# 415 : :
# 416 : : // Scroll debug.log if it's getting too big
# 417 : 0 : FILE* file = fsbridge::fopen(m_file_path, "r");
# 418 : :
# 419 : : // Special files (e.g. device nodes) may not have a size.
# 420 : 0 : size_t log_size = 0;
# 421 : 0 : try {
# 422 : 0 : log_size = fs::file_size(m_file_path);
# 423 : 0 : } catch (const fs::filesystem_error&) {}
# 424 : :
# 425 : : // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE
# 426 : : // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes
# 427 [ # # ][ # # ]: 0 : if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10))
# 428 : 0 : {
# 429 : : // Restart the file with some of the end
# 430 : 0 : std::vector<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
# 431 [ # # ]: 0 : if (fseek(file, -((long)vch.size()), SEEK_END)) {
# 432 : 0 : LogPrintf("Failed to shrink debug log file: fseek(...) failed\n");
# 433 : 0 : fclose(file);
# 434 : 0 : return;
# 435 : 0 : }
# 436 : 0 : int nBytes = fread(vch.data(), 1, vch.size(), file);
# 437 : 0 : fclose(file);
# 438 : :
# 439 : 0 : file = fsbridge::fopen(m_file_path, "w");
# 440 [ # # ]: 0 : if (file)
# 441 : 0 : {
# 442 : 0 : fwrite(vch.data(), 1, nBytes, file);
# 443 : 0 : fclose(file);
# 444 : 0 : }
# 445 : 0 : }
# 446 [ # # ]: 0 : else if (file != nullptr)
# 447 : 0 : fclose(file);
# 448 : 0 : }
|
