diff --git a/src/logging.cpp b/src/logging.cpp index cac426ec4..1315fe57b 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -1,352 +1,352 @@ // Copyright (c) 2009-2010 Satoshi Nakamoto // Copyright (c) 2009-2016 The Bitcoin Core developers // Copyright (c) 2017-2019 The Bitcoin developers // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include #include #include bool fLogIPs = DEFAULT_LOGIPS; const char *const DEFAULT_DEBUGLOGFILE = "debug.log"; BCLog::Logger &LogInstance() { /** * NOTE: the logger instance is leaked on exit. This is ugly, but will be * cleaned up by the OS/libc. Defining a logger as a global object doesn't * work since the order of destruction of static/global objects is * undefined. Consider if the logger gets destroyed, and then some later * destructor calls LogPrintf, maybe indirectly, and you get a core dump at * shutdown trying to access the logger. When the shutdown sequence is fully * audited and tested, explicit destruction of these objects can be * implemented by changing this from a raw pointer to a std::unique_ptr. - * Since the destructor is never called, the logger and all its members must - * have a trivial destructor. + * Since the ~Logger() destructor is never called, the Logger class and all + * its subclasses must have implicitly-defined destructors. * * This method of initialization was originally introduced in * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c. */ static BCLog::Logger *g_logger{new BCLog::Logger()}; return *g_logger; } static int FileWriteStr(const std::string &str, FILE *fp) { return fwrite(str.data(), 1, str.size(), fp); } bool BCLog::Logger::StartLogging() { std::lock_guard scoped_lock(m_cs); assert(m_buffering); assert(m_fileout == nullptr); if (m_print_to_file) { assert(!m_file_path.empty()); m_fileout = fsbridge::fopen(m_file_path, "a"); if (!m_fileout) { return false; } // Unbuffered. setbuf(m_fileout, nullptr); // Add newlines to the logfile to distinguish this execution from the // last one. FileWriteStr("\n\n\n\n\n", m_fileout); } // Dump buffered messages from before we opened the log. m_buffering = false; while (!m_msgs_before_open.empty()) { const std::string &s = m_msgs_before_open.front(); if (m_print_to_file) { FileWriteStr(s, m_fileout); } if (m_print_to_console) { fwrite(s.data(), 1, s.size(), stdout); } for (const auto &cb : m_print_callbacks) { cb(s); } m_msgs_before_open.pop_front(); } if (m_print_to_console) { fflush(stdout); } return true; } void BCLog::Logger::DisconnectTestLogger() { std::lock_guard scoped_lock(m_cs); m_buffering = true; if (m_fileout != nullptr) { fclose(m_fileout); } m_fileout = nullptr; m_print_callbacks.clear(); } struct CLogCategoryDesc { BCLog::LogFlags flag; std::string category; }; const CLogCategoryDesc LogCategories[] = { {BCLog::NONE, "0"}, {BCLog::NONE, "none"}, {BCLog::NET, "net"}, {BCLog::TOR, "tor"}, {BCLog::MEMPOOL, "mempool"}, {BCLog::HTTP, "http"}, {BCLog::BENCH, "bench"}, {BCLog::ZMQ, "zmq"}, {BCLog::DB, "db"}, {BCLog::RPC, "rpc"}, {BCLog::ESTIMATEFEE, "estimatefee"}, {BCLog::ADDRMAN, "addrman"}, {BCLog::SELECTCOINS, "selectcoins"}, {BCLog::REINDEX, "reindex"}, {BCLog::CMPCTBLOCK, "cmpctblock"}, {BCLog::RAND, "rand"}, {BCLog::PRUNE, "prune"}, {BCLog::PROXY, "proxy"}, {BCLog::MEMPOOLREJ, "mempoolrej"}, {BCLog::LIBEVENT, "libevent"}, {BCLog::COINDB, "coindb"}, {BCLog::QT, "qt"}, {BCLog::LEVELDB, "leveldb"}, {BCLog::VALIDATION, "validation"}, {BCLog::ALL, "1"}, {BCLog::ALL, "all"}, }; bool GetLogCategory(BCLog::LogFlags &flag, const std::string &str) { if (str == "") { flag = BCLog::ALL; return true; } for (const CLogCategoryDesc &category_desc : LogCategories) { if (category_desc.category == str) { flag = category_desc.flag; return true; } } return false; } std::string ListLogCategories() { std::string ret; int outcount = 0; for (const CLogCategoryDesc &category_desc : LogCategories) { // Omit the special cases. if (category_desc.flag != BCLog::NONE && category_desc.flag != BCLog::ALL) { if (outcount != 0) { ret += ", "; } ret += category_desc.category; outcount++; } } return ret; } std::vector ListActiveLogCategories() { std::vector ret; for (const CLogCategoryDesc &category_desc : LogCategories) { // Omit the special cases. if (category_desc.flag != BCLog::NONE && category_desc.flag != BCLog::ALL) { CLogCategoryActive catActive; catActive.category = category_desc.category; catActive.active = LogAcceptCategory(category_desc.flag); ret.push_back(catActive); } } return ret; } BCLog::Logger::~Logger() { if (m_fileout) { fclose(m_fileout); } } std::string BCLog::Logger::LogTimestampStr(const std::string &str) { std::string strStamped; if (!m_log_timestamps) { return str; } if (m_started_new_line) { int64_t nTimeMicros = GetTimeMicros(); strStamped = FormatISO8601DateTime(nTimeMicros / 1000000); if (m_log_time_micros) { strStamped.pop_back(); strStamped += strprintf(".%06dZ", nTimeMicros % 1000000); } int64_t mocktime = GetMockTime(); if (mocktime) { strStamped += " (mocktime: " + FormatISO8601DateTime(mocktime) + ")"; } strStamped += ' ' + str; } else { strStamped = str; } return strStamped; } namespace BCLog { /** Belts and suspenders: make sure outgoing log messages don't contain * potentially suspicious characters, such as terminal control codes. * * This escapes control characters except newline ('\n') in C syntax. * It escapes instead of removes them to still allow for troubleshooting * issues where they accidentally end up in strings. */ std::string LogEscapeMessage(const std::string &str) { std::string ret; for (char ch_in : str) { uint8_t ch = (uint8_t)ch_in; if ((ch >= 32 || ch == '\n') && ch != '\x7f') { ret += ch_in; } else { ret += strprintf("\\x%02x", ch); } } return ret; } } // namespace BCLog void BCLog::Logger::LogPrintStr(const std::string &str) { std::lock_guard scoped_lock(m_cs); std::string str_prefixed = LogEscapeMessage(str); if (m_log_threadnames && m_started_new_line) { str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] "); } str_prefixed = LogTimestampStr(str_prefixed); m_started_new_line = !str.empty() && str[str.size() - 1] == '\n'; if (m_buffering) { // buffer if we haven't started logging yet m_msgs_before_open.push_back(str_prefixed); return; } if (m_print_to_console) { // Print to console. fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout); fflush(stdout); } for (const auto &cb : m_print_callbacks) { cb(str_prefixed); } if (m_print_to_file) { assert(m_fileout != nullptr); // Reopen the log file, if requested. if (m_reopen_file) { m_reopen_file = false; FILE *new_fileout = fsbridge::fopen(m_file_path, "a"); if (new_fileout) { // unbuffered. setbuf(m_fileout, nullptr); fclose(m_fileout); m_fileout = new_fileout; } } FileWriteStr(str_prefixed, m_fileout); } } void BCLog::Logger::ShrinkDebugFile() { // Amount of debug.log to save at end when shrinking (must fit in memory) constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000; assert(!m_file_path.empty()); // Scroll debug.log if it's getting too big. FILE *file = fsbridge::fopen(m_file_path, "r"); // Special files (e.g. device nodes) may not have a size. size_t log_size = 0; try { log_size = fs::file_size(m_file_path); } catch (const fs::filesystem_error &) { } // If debug.log file is more than 10% bigger the RECENT_DEBUG_HISTORY_SIZE // trim it down by saving only the last RECENT_DEBUG_HISTORY_SIZE bytes. if (file && log_size > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10)) { // Restart the file with some of the end. std::vector vch(RECENT_DEBUG_HISTORY_SIZE, 0); if (fseek(file, -((long)vch.size()), SEEK_END)) { LogPrintf("Failed to shrink debug log file: fseek(...) failed\n"); fclose(file); return; } int nBytes = fread(vch.data(), 1, vch.size(), file); fclose(file); file = fsbridge::fopen(m_file_path, "w"); if (file) { fwrite(vch.data(), 1, nBytes, file); fclose(file); } } else if (file != nullptr) { fclose(file); } } void BCLog::Logger::EnableCategory(LogFlags category) { m_categories |= category; } bool BCLog::Logger::EnableCategory(const std::string &str) { BCLog::LogFlags flag; if (!GetLogCategory(flag, str)) { return false; } EnableCategory(flag); return true; } void BCLog::Logger::DisableCategory(LogFlags category) { m_categories &= ~category; } bool BCLog::Logger::DisableCategory(const std::string &str) { BCLog::LogFlags flag; if (!GetLogCategory(flag, str)) { return false; } DisableCategory(flag); return true; } bool BCLog::Logger::WillLogCategory(LogFlags category) const { // ALL is not meant to be used as a logging category, but only as a mask // representing all categories. if (category == BCLog::NONE || category == BCLog::ALL) { LogPrintf("Error trying to log using a category mask instead of an " "explicit category.\n"); return true; } return (m_categories.load(std::memory_order_relaxed) & category) != 0; } bool BCLog::Logger::DefaultShrinkDebugFile() const { return m_categories != BCLog::NONE; } diff --git a/src/sync.cpp b/src/sync.cpp index fbffb4b69..682dea643 100644 --- a/src/sync.cpp +++ b/src/sync.cpp @@ -1,234 +1,264 @@ // Copyright (c) 2011-2016 The Bitcoin Core developers // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. #include #include +#include #include #include #include #include #include #include +#include +#include +#include +#include #ifdef DEBUG_LOCKCONTENTION void PrintLockContention(const char *pszName, const char *pszFile, int nLine) { LogPrintf("LOCKCONTENTION: %s\n", pszName); LogPrintf("Locker: %s:%d\n", pszFile, nLine); } #endif /* DEBUG_LOCKCONTENTION */ #ifdef DEBUG_LOCKORDER // // Early deadlock detection. // Problem being solved: // Thread 1 locks A, then B, then C // Thread 2 locks D, then C, then A // --> may result in deadlock between the two threads, depending on when // they run. // Solution implemented here: // Keep track of pairs of locks: (A before B), (A before C), etc. // Complain if any thread tries to lock in a different order. // struct CLockLocation { CLockLocation(const char *pszName, const char *pszFile, int nLine, bool fTryIn, const std::string &thread_name) : fTry(fTryIn), mutexName(pszName), sourceFile(pszFile), m_thread_name(thread_name), sourceLine(nLine) {} std::string ToString() const { return strprintf("%s %s:%s%s (in thread %s)", mutexName, sourceFile, itostr(sourceLine), (fTry ? " (TRY)" : ""), m_thread_name); } std::string Name() const { return mutexName; } private: bool fTry; std::string mutexName; std::string sourceFile; const std::string &m_thread_name; int sourceLine; }; -typedef std::vector> LockStack; -typedef std::map, LockStack> LockOrders; -typedef std::set> InvLockOrders; +using LockStackItem = std::pair; +using LockStack = std::vector; +using LockStacks = std::unordered_map; -struct LockData { - // Very ugly hack: as the global constructs and destructors run single - // threaded, we use this boolean to know whether LockData still exists, - // as DeleteLock can get called by global RecursiveMutex destructors - // after LockData disappears. - bool available; - LockData() : available(true) {} - ~LockData() { available = false; } +using LockPair = std::pair; +using LockOrders = std::map; +using InvLockOrders = std::set; +struct LockData { + LockStacks m_lock_stacks; LockOrders lockorders; InvLockOrders invlockorders; std::mutex dd_mutex; }; + LockData &GetLockData() { - static LockData lockdata; - return lockdata; + // This approach guarantees that the object is not destroyed until after its + // last use. The operating system automatically reclaims all the memory in a + // program's heap when that program exits. + // Since the ~LockData() destructor is never called, the LockData class and + // all its subclasses must have implicitly-defined destructors. + static LockData &lock_data = *new LockData(); + return lock_data; } -static thread_local LockStack g_lockstack; - -static void -potential_deadlock_detected(const std::pair &mismatch, - const LockStack &s1, const LockStack &s2) { +static void potential_deadlock_detected(const LockPair &mismatch, + const LockStack &s1, + const LockStack &s2) { LogPrintf("POTENTIAL DEADLOCK DETECTED\n"); LogPrintf("Previous lock order was:\n"); - for (const std::pair &i : s2) { + for (const LockStackItem &i : s2) { if (i.first == mismatch.first) { LogPrintfToBeContinued(" (1)"); } if (i.first == mismatch.second) { LogPrintfToBeContinued(" (2)"); } LogPrintf(" %s\n", i.second.ToString()); } LogPrintf("Current lock order is:\n"); - for (const std::pair &i : s1) { + for (const LockStackItem &i : s1) { if (i.first == mismatch.first) { LogPrintfToBeContinued(" (1)"); } if (i.first == mismatch.second) { LogPrintfToBeContinued(" (2)"); } LogPrintf(" %s\n", i.second.ToString()); } if (g_debug_lockorder_abort) { tfm::format( std::cerr, "Assertion failed: detected inconsistent lock order at %s:%i, " "details in debug log.\n", __FILE__, __LINE__); abort(); } throw std::logic_error("potential deadlock detected"); } static void push_lock(void *c, const CLockLocation &locklocation) { LockData &lockdata = GetLockData(); std::lock_guard lock(lockdata.dd_mutex); - g_lockstack.push_back(std::make_pair(c, locklocation)); - - for (const std::pair &i : g_lockstack) { + LockStack &lock_stack = lockdata.m_lock_stacks[std::this_thread::get_id()]; + lock_stack.emplace_back(c, locklocation); + for (const LockStackItem &i : lock_stack) { if (i.first == c) { break; } - std::pair p1 = std::make_pair(i.first, c); + const LockPair p1 = std::make_pair(i.first, c); if (lockdata.lockorders.count(p1)) { continue; } - lockdata.lockorders.emplace(p1, g_lockstack); + lockdata.lockorders.emplace(p1, lock_stack); - std::pair p2 = std::make_pair(c, i.first); + const LockPair p2 = std::make_pair(c, i.first); lockdata.invlockorders.insert(p2); if (lockdata.lockorders.count(p2)) { potential_deadlock_detected(p1, lockdata.lockorders[p2], lockdata.lockorders[p1]); } } } static void pop_lock() { - g_lockstack.pop_back(); + LockData &lockdata = GetLockData(); + std::lock_guard lock(lockdata.dd_mutex); + + LockStack &lock_stack = lockdata.m_lock_stacks[std::this_thread::get_id()]; + lock_stack.pop_back(); + if (lock_stack.empty()) { + lockdata.m_lock_stacks.erase(std::this_thread::get_id()); + } } void EnterCritical(const char *pszName, const char *pszFile, int nLine, void *cs, bool fTry) { push_lock(cs, CLockLocation(pszName, pszFile, nLine, fTry, util::ThreadGetInternalName())); } void CheckLastCritical(void *cs, std::string &lockname, const char *guardname, const char *file, int line) { - if (!g_lockstack.empty()) { - const auto &lastlock = g_lockstack.back(); - if (lastlock.first == cs) { - lockname = lastlock.second.Name(); - return; + { + LockData &lockdata = GetLockData(); + std::lock_guard lock(lockdata.dd_mutex); + + const LockStack &lock_stack = + lockdata.m_lock_stacks[std::this_thread::get_id()]; + if (!lock_stack.empty()) { + const auto &lastlock = lock_stack.back(); + if (lastlock.first == cs) { + lockname = lastlock.second.Name(); + return; + } } } throw std::system_error( EPERM, std::generic_category(), strprintf("%s:%s %s was not most recent critical section locked", file, line, guardname)); } void LeaveCritical() { pop_lock(); } std::string LocksHeld() { + LockData &lockdata = GetLockData(); + std::lock_guard lock(lockdata.dd_mutex); + + const LockStack &lock_stack = + lockdata.m_lock_stacks[std::this_thread::get_id()]; std::string result; - for (const std::pair &i : g_lockstack) { + for (const LockStackItem &i : lock_stack) { result += i.second.ToString() + std::string("\n"); } return result; } +static bool LockHeld(void *mutex) { + LockData &lockdata = GetLockData(); + std::lock_guard lock(lockdata.dd_mutex); + + const LockStack &lock_stack = + lockdata.m_lock_stacks[std::this_thread::get_id()]; + for (const LockStackItem &i : lock_stack) { + if (i.first == mutex) { + return true; + } + } + + return false; +} + void AssertLockHeldInternal(const char *pszName, const char *pszFile, int nLine, void *cs) { - for (const std::pair &i : g_lockstack) { - if (i.first == cs) { - return; - } + if (LockHeld(cs)) { + return; } tfm::format(std::cerr, "Assertion failed: lock %s not held in %s:%i; locks held:\n%s", pszName, pszFile, nLine, LocksHeld()); abort(); } void AssertLockNotHeldInternal(const char *pszName, const char *pszFile, int nLine, void *cs) { - for (const std::pair &i : g_lockstack) { - if (i.first == cs) { - tfm::format( - std::cerr, + if (!LockHeld(cs)) { + return; + } + tfm::format(std::cerr, "Assertion failed: lock %s held in %s:%i; locks held:\n%s", pszName, pszFile, nLine, LocksHeld()); - abort(); - } - } + abort(); } void DeleteLock(void *cs) { LockData &lockdata = GetLockData(); - if (!lockdata.available) { - // We're already shutting down. - return; - } - std::lock_guard lock(lockdata.dd_mutex); - std::pair item = std::make_pair(cs, nullptr); + const LockPair item = std::make_pair(cs, nullptr); LockOrders::iterator it = lockdata.lockorders.lower_bound(item); while (it != lockdata.lockorders.end() && it->first.first == cs) { - std::pair invitem = + const LockPair invitem = std::make_pair(it->first.second, it->first.first); lockdata.invlockorders.erase(invitem); lockdata.lockorders.erase(it++); } InvLockOrders::iterator invit = lockdata.invlockorders.lower_bound(item); while (invit != lockdata.invlockorders.end() && invit->first == cs) { - std::pair invinvitem = - std::make_pair(invit->second, invit->first); + const LockPair invinvitem = std::make_pair(invit->second, invit->first); lockdata.lockorders.erase(invinvitem); lockdata.invlockorders.erase(invit++); } } bool g_debug_lockorder_abort = true; #endif /* DEBUG_LOCKORDER */