diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -65,6 +65,7 @@ compat/glibcxx_sanity.cpp compat/strnlen.cpp fs.cpp + logging.cpp random.cpp rpc/protocol.cpp support/cleanse.cpp diff --git a/src/Makefile.am b/src/Makefile.am --- a/src/Makefile.am +++ b/src/Makefile.am @@ -122,6 +122,7 @@ keystore.h \ dbwrapper.h \ limitedmap.h \ + logging.h \ memusage.h \ merkleblock.h \ miner.h \ @@ -364,6 +365,7 @@ compat/glibcxx_sanity.cpp \ compat/strnlen.cpp \ fs.cpp \ + logging.cpp \ random.cpp \ rpc/protocol.cpp \ support/cleanse.cpp \ diff --git a/src/logging.h b/src/logging.h new file mode 100644 --- /dev/null +++ b/src/logging.h @@ -0,0 +1,85 @@ +// Copyright (c) 2009-2010 Satoshi Nakamoto +// Copyright (c) 2009-2016 The Bitcoin Core developers +// Copyright (c) 2017-2018 The Bitcoin developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#ifndef BITCOIN_LOGGING_H +#define BITCOIN_LOGGING_H + +#include +#include +#include + +static const bool DEFAULT_LOGTIMEMICROS = false; +static const bool DEFAULT_LOGIPS = false; +static const bool DEFAULT_LOGTIMESTAMPS = true; + +extern bool fPrintToConsole; +extern bool fPrintToDebugLog; + +extern bool fLogTimestamps; +extern bool fLogTimeMicros; +extern bool fLogIPs; +extern std::atomic fReopenDebugLog; + +extern std::atomic logCategories; + +namespace BCLog { +enum LogFlags : uint32_t { + NONE = 0, + NET = (1 << 0), + TOR = (1 << 1), + MEMPOOL = (1 << 2), + HTTP = (1 << 3), + BENCH = (1 << 4), + ZMQ = (1 << 5), + DB = (1 << 6), + RPC = (1 << 7), + ESTIMATEFEE = (1 << 8), + ADDRMAN = (1 << 9), + SELECTCOINS = (1 << 10), + REINDEX = (1 << 11), + CMPCTBLOCK = (1 << 12), + RAND = (1 << 13), + PRUNE = (1 << 14), + PROXY = (1 << 15), + MEMPOOLREJ = (1 << 16), + LIBEVENT = (1 << 17), + COINDB = (1 << 18), + QT = (1 << 19), + LEVELDB = (1 << 20), + ALL = ~uint32_t(0), +}; +} + +/** Return true if log accepts specified category */ +static inline bool LogAcceptCategory(uint32_t category) { + return (logCategories.load(std::memory_order_relaxed) & category) != 0; +} + +/** Returns a string with the supported log categories */ +std::string ListLogCategories(); + +/** Return true if str parses as a log category and set the flags in f */ +bool GetLogCategory(uint32_t *f, const std::string *str); + +/** Send a string to the log output */ +int LogPrintStr(const std::string &str); + +#define LogPrint(category, ...) \ + do { \ + if (LogAcceptCategory((category))) { \ + LogPrintStr(tfm::format(__VA_ARGS__)); \ + } \ + } while (0) + +#define LogPrintf(...) \ + do { \ + LogPrintStr(tfm::format(__VA_ARGS__)); \ + } while (0) + +void OpenDebugLog(); +void ShrinkDebugFile(); + +#endif // BITCOIN_LOGGING_H diff --git a/src/logging.cpp b/src/logging.cpp new file mode 100644 --- /dev/null +++ b/src/logging.cpp @@ -0,0 +1,237 @@ +// Copyright (c) 2009-2010 Satoshi Nakamoto +// Copyright (c) 2009-2016 The Bitcoin Core developers +// Copyright (c) 2017-2018 The Bitcoin developers +// Distributed under the MIT software license, see the accompanying +// file COPYING or http://www.opensource.org/licenses/mit-license.php. + +#include "logging.h" +#include "util.h" +#include "utilstrencodings.h" +#include "utiltime.h" + +#include +#include + +bool fPrintToConsole = false; +bool fPrintToDebugLog = true; + +bool fLogTimestamps = DEFAULT_LOGTIMESTAMPS; +bool fLogTimeMicros = DEFAULT_LOGTIMEMICROS; +bool fLogIPs = DEFAULT_LOGIPS; +std::atomic fReopenDebugLog(false); + +/** + * Log categories bitfield. Leveldb/libevent need special handling if their + * flags are changed at runtime. + */ +std::atomic logCategories(0); + +/** + * LogPrintf() has been broken a couple of times now by well-meaning people + * adding mutexes in the most straightforward way. It breaks because it may be + * called by global destructors during shutdown. Since the order of destruction + * of static/global objects is undefined, defining a mutex as a global object + * doesn't work (the mutex gets destroyed, and then some later destructor calls + * OutputDebugStringF, maybe indirectly, and you get a core dump at shutdown + * trying to lock the mutex). + */ +static boost::once_flag debugPrintInitFlag = BOOST_ONCE_INIT; + +/** + * We use boost::call_once() to make sure mutexDebugLog and vMsgsBeforeOpenLog + * are initialized in a thread-safe manner. + * + * NOTE: fileout, mutexDebugLog and sometimes vMsgsBeforeOpenLog are leaked on + * exit. This is ugly, but will be cleaned up by the OS/libc. When the shutdown + * sequence is fully audited and tested, explicit destruction of these objects + * can be implemented. + */ +static FILE *fileout = nullptr; +static boost::mutex *mutexDebugLog = nullptr; +static std::list *vMsgsBeforeOpenLog; + +static int FileWriteStr(const std::string &str, FILE *fp) { + return fwrite(str.data(), 1, str.size(), fp); +} + +static void DebugPrintInit() { + assert(mutexDebugLog == nullptr); + mutexDebugLog = new boost::mutex(); + vMsgsBeforeOpenLog = new std::list; +} + +void OpenDebugLog() { + boost::call_once(&DebugPrintInit, debugPrintInitFlag); + boost::mutex::scoped_lock scoped_lock(*mutexDebugLog); + + assert(fileout == nullptr); + assert(vMsgsBeforeOpenLog); + fs::path pathDebug = GetDataDir() / "debug.log"; + fileout = fsbridge::fopen(pathDebug, "a"); + if (fileout) { + // Unbuffered. + setbuf(fileout, nullptr); + // Dump buffered messages from before we opened the log. + while (!vMsgsBeforeOpenLog->empty()) { + FileWriteStr(vMsgsBeforeOpenLog->front(), fileout); + vMsgsBeforeOpenLog->pop_front(); + } + } + + delete vMsgsBeforeOpenLog; + vMsgsBeforeOpenLog = nullptr; +} + +struct CLogCategoryDesc { + uint32_t flag; + std::string category; +}; + +const CLogCategoryDesc LogCategories[] = { + {BCLog::NONE, "0"}, + {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::ALL, "1"}, + {BCLog::ALL, "all"}, +}; + +bool GetLogCategory(uint32_t *f, const std::string *str) { + if (f && str) { + if (*str == "") { + *f = BCLog::ALL; + return true; + } + for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { + if (LogCategories[i].category == *str) { + *f = LogCategories[i].flag; + return true; + } + } + } + return false; +} + +std::string ListLogCategories() { + std::string ret; + int outcount = 0; + for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { + // Omit the special cases. + if (LogCategories[i].flag != BCLog::NONE && + LogCategories[i].flag != BCLog::ALL) { + if (outcount != 0) ret += ", "; + ret += LogCategories[i].category; + outcount++; + } + } + return ret; +} + +/** + * fStartedNewLine is a state variable held by the calling context that will + * suppress printing of the timestamp when multiple calls are made that don't + * end in a newline. Initialize it to true, and hold it, in the calling context. + */ +static std::string LogTimestampStr(const std::string &str, + std::atomic_bool *fStartedNewLine) { + std::string strStamped; + + if (!fLogTimestamps) return str; + + if (*fStartedNewLine) { + int64_t nTimeMicros = GetLogTimeMicros(); + strStamped = + DateTimeStrFormat("%Y-%m-%d %H:%M:%S", nTimeMicros / 1000000); + if (fLogTimeMicros) + strStamped += strprintf(".%06d", nTimeMicros % 1000000); + strStamped += ' ' + str; + } else + strStamped = str; + + if (!str.empty() && str[str.size() - 1] == '\n') + *fStartedNewLine = true; + else + *fStartedNewLine = false; + + return strStamped; +} + +int LogPrintStr(const std::string &str) { + // Returns total number of characters written. + int ret = 0; + static std::atomic_bool fStartedNewLine(true); + + std::string strTimestamped = LogTimestampStr(str, &fStartedNewLine); + + if (fPrintToConsole) { + // Print to console. + ret = fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout); + fflush(stdout); + } else if (fPrintToDebugLog) { + boost::call_once(&DebugPrintInit, debugPrintInitFlag); + boost::mutex::scoped_lock scoped_lock(*mutexDebugLog); + + // Buffer if we haven't opened the log yet. + if (fileout == nullptr) { + assert(vMsgsBeforeOpenLog); + ret = strTimestamped.length(); + vMsgsBeforeOpenLog->push_back(strTimestamped); + } else { + // Reopen the log file, if requested. + if (fReopenDebugLog) { + fReopenDebugLog = false; + fs::path pathDebug = GetDataDir() / "debug.log"; + if (fsbridge::freopen(pathDebug, "a", fileout) != nullptr) { + // unbuffered. + setbuf(fileout, nullptr); + } + } + + ret = FileWriteStr(strTimestamped, fileout); + } + } + return ret; +} + +void ShrinkDebugFile() { + // Amount of debug.log to save at end when shrinking (must fit in memory) + constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000; + // Scroll debug.log if it's getting too big. + fs::path pathLog = GetDataDir() / "debug.log"; + FILE *file = fsbridge::fopen(pathLog, "r"); + // 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 && + fs::file_size(pathLog) > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10)) { + // Restart the file with some of the end. + std::vector vch(RECENT_DEBUG_HISTORY_SIZE, 0); + fseek(file, -((long)vch.size()), SEEK_END); + int nBytes = fread(vch.data(), 1, vch.size(), file); + fclose(file); + + file = fsbridge::fopen(pathLog, "w"); + if (file) { + fwrite(vch.data(), 1, nBytes, file); + fclose(file); + } + } else if (file != nullptr) + fclose(file); +} diff --git a/src/util.h b/src/util.h --- a/src/util.h +++ b/src/util.h @@ -4,7 +4,7 @@ // file COPYING or http://www.opensource.org/licenses/mit-license.php. /** - * Server/client environment: argument handling, config file parsing, logging, + * Server/client environment: argument handling, config file parsing, * thread wrappers, startup time */ #ifndef BITCOIN_UTIL_H @@ -16,6 +16,7 @@ #include "compat.h" #include "fs.h" +#include "logging.h" #include "sync.h" #include "tinyformat.h" #include "utiltime.h" @@ -33,10 +34,6 @@ // Application startup time (used for uptime calculation) int64_t GetStartupTime(); -static const bool DEFAULT_LOGTIMEMICROS = false; -static const bool DEFAULT_LOGIPS = false; -static const bool DEFAULT_LOGTIMESTAMPS = true; - /** Signals for translation. */ class CTranslationInterface { public: @@ -44,20 +41,11 @@ boost::signals2::signal Translate; }; -extern bool fPrintToConsole; -extern bool fPrintToDebugLog; - -extern bool fLogTimestamps; -extern bool fLogTimeMicros; -extern bool fLogIPs; -extern std::atomic fReopenDebugLog; extern CTranslationInterface translationInterface; extern const char *const BITCOIN_CONF_FILENAME; extern const char *const BITCOIN_PID_FILENAME; -extern std::atomic logCategories; - /** * Translation function: Call Translate signal on UI interface, which returns a * boost::optional result. If no translation slot is registered, nothing is @@ -71,60 +59,6 @@ void SetupEnvironment(); bool SetupNetworking(); -namespace BCLog { -enum LogFlags : uint32_t { - NONE = 0, - NET = (1 << 0), - TOR = (1 << 1), - MEMPOOL = (1 << 2), - HTTP = (1 << 3), - BENCH = (1 << 4), - ZMQ = (1 << 5), - DB = (1 << 6), - RPC = (1 << 7), - ESTIMATEFEE = (1 << 8), - ADDRMAN = (1 << 9), - SELECTCOINS = (1 << 10), - REINDEX = (1 << 11), - CMPCTBLOCK = (1 << 12), - RAND = (1 << 13), - PRUNE = (1 << 14), - PROXY = (1 << 15), - MEMPOOLREJ = (1 << 16), - LIBEVENT = (1 << 17), - COINDB = (1 << 18), - QT = (1 << 19), - LEVELDB = (1 << 20), - ALL = ~uint32_t(0), -}; -} - -/** Return true if log accepts specified category */ -static inline bool LogAcceptCategory(uint32_t category) { - return (logCategories.load(std::memory_order_relaxed) & category) != 0; -} - -/** Returns a string with the supported log categories */ -std::string ListLogCategories(); - -/** Return true if str parses as a log category and set the flags in f */ -bool GetLogCategory(uint32_t *f, const std::string *str); - -/** Send a string to the log output */ -int LogPrintStr(const std::string &str); - -#define LogPrint(category, ...) \ - do { \ - if (LogAcceptCategory((category))) { \ - LogPrintStr(tfm::format(__VA_ARGS__)); \ - } \ - } while (0) - -#define LogPrintf(...) \ - do { \ - LogPrintStr(tfm::format(__VA_ARGS__)); \ - } while (0) - template bool error(const char *fmt, const Args &... args) { LogPrintStr("ERROR: " + tfm::format(fmt, args...) + "\n"); return false; @@ -148,8 +82,6 @@ #ifdef WIN32 fs::path GetSpecialFolderPath(int nFolder, bool fCreate = true); #endif -void OpenDebugLog(); -void ShrinkDebugFile(); void runCommand(const std::string &strCommand); inline bool IsSwitchChar(char c) { diff --git a/src/util.cpp b/src/util.cpp --- a/src/util.cpp +++ b/src/util.cpp @@ -94,21 +94,9 @@ const char *const BITCOIN_PID_FILENAME = "bitcoind.pid"; ArgsManager gArgs; -bool fPrintToConsole = false; -bool fPrintToDebugLog = true; -bool fLogTimestamps = DEFAULT_LOGTIMESTAMPS; -bool fLogTimeMicros = DEFAULT_LOGTIMEMICROS; -bool fLogIPs = DEFAULT_LOGIPS; -std::atomic fReopenDebugLog(false); CTranslationInterface translationInterface; -/** - * Log categories bitfield. Leveldb/libevent need special handling if their - * flags are changed at runtime. - */ -std::atomic logCategories(0); - /** Init OpenSSL library multithreading support */ static CCriticalSection **ppmutexOpenSSL; void locking_callback(int mode, int i, const char *file, @@ -159,191 +147,6 @@ } } instance_of_cinit; -/** - * LogPrintf() has been broken a couple of times now by well-meaning people - * adding mutexes in the most straightforward way. It breaks because it may be - * called by global destructors during shutdown. Since the order of destruction - * of static/global objects is undefined, defining a mutex as a global object - * doesn't work (the mutex gets destroyed, and then some later destructor calls - * OutputDebugStringF, maybe indirectly, and you get a core dump at shutdown - * trying to lock the mutex). - */ -static boost::once_flag debugPrintInitFlag = BOOST_ONCE_INIT; - -/** - * We use boost::call_once() to make sure mutexDebugLog and vMsgsBeforeOpenLog - * are initialized in a thread-safe manner. - * - * NOTE: fileout, mutexDebugLog and sometimes vMsgsBeforeOpenLog are leaked on - * exit. This is ugly, but will be cleaned up by the OS/libc. When the shutdown - * sequence is fully audited and tested, explicit destruction of these objects - * can be implemented. - */ -static FILE *fileout = nullptr; -static boost::mutex *mutexDebugLog = nullptr; -static std::list *vMsgsBeforeOpenLog; - -static int FileWriteStr(const std::string &str, FILE *fp) { - return fwrite(str.data(), 1, str.size(), fp); -} - -static void DebugPrintInit() { - assert(mutexDebugLog == nullptr); - mutexDebugLog = new boost::mutex(); - vMsgsBeforeOpenLog = new std::list; -} - -void OpenDebugLog() { - boost::call_once(&DebugPrintInit, debugPrintInitFlag); - boost::mutex::scoped_lock scoped_lock(*mutexDebugLog); - - assert(fileout == nullptr); - assert(vMsgsBeforeOpenLog); - fs::path pathDebug = GetDataDir() / "debug.log"; - fileout = fsbridge::fopen(pathDebug, "a"); - if (fileout) { - // Unbuffered. - setbuf(fileout, nullptr); - // Dump buffered messages from before we opened the log. - while (!vMsgsBeforeOpenLog->empty()) { - FileWriteStr(vMsgsBeforeOpenLog->front(), fileout); - vMsgsBeforeOpenLog->pop_front(); - } - } - - delete vMsgsBeforeOpenLog; - vMsgsBeforeOpenLog = nullptr; -} - -struct CLogCategoryDesc { - uint32_t flag; - std::string category; -}; - -const CLogCategoryDesc LogCategories[] = { - {BCLog::NONE, "0"}, - {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::ALL, "1"}, - {BCLog::ALL, "all"}, -}; - -bool GetLogCategory(uint32_t *f, const std::string *str) { - if (f && str) { - if (*str == "") { - *f = BCLog::ALL; - return true; - } - for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { - if (LogCategories[i].category == *str) { - *f = LogCategories[i].flag; - return true; - } - } - } - return false; -} - -std::string ListLogCategories() { - std::string ret; - int outcount = 0; - for (unsigned int i = 0; i < ARRAYLEN(LogCategories); i++) { - // Omit the special cases. - if (LogCategories[i].flag != BCLog::NONE && - LogCategories[i].flag != BCLog::ALL) { - if (outcount != 0) ret += ", "; - ret += LogCategories[i].category; - outcount++; - } - } - return ret; -} - -/** - * fStartedNewLine is a state variable held by the calling context that will - * suppress printing of the timestamp when multiple calls are made that don't - * end in a newline. Initialize it to true, and hold it, in the calling context. - */ -static std::string LogTimestampStr(const std::string &str, - std::atomic_bool *fStartedNewLine) { - std::string strStamped; - - if (!fLogTimestamps) return str; - - if (*fStartedNewLine) { - int64_t nTimeMicros = GetLogTimeMicros(); - strStamped = - DateTimeStrFormat("%Y-%m-%d %H:%M:%S", nTimeMicros / 1000000); - if (fLogTimeMicros) - strStamped += strprintf(".%06d", nTimeMicros % 1000000); - strStamped += ' ' + str; - } else - strStamped = str; - - if (!str.empty() && str[str.size() - 1] == '\n') - *fStartedNewLine = true; - else - *fStartedNewLine = false; - - return strStamped; -} - -int LogPrintStr(const std::string &str) { - // Returns total number of characters written. - int ret = 0; - static std::atomic_bool fStartedNewLine(true); - - std::string strTimestamped = LogTimestampStr(str, &fStartedNewLine); - - if (fPrintToConsole) { - // Print to console. - ret = fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout); - fflush(stdout); - } else if (fPrintToDebugLog) { - boost::call_once(&DebugPrintInit, debugPrintInitFlag); - boost::mutex::scoped_lock scoped_lock(*mutexDebugLog); - - // Buffer if we haven't opened the log yet. - if (fileout == nullptr) { - assert(vMsgsBeforeOpenLog); - ret = strTimestamped.length(); - vMsgsBeforeOpenLog->push_back(strTimestamped); - } else { - // Reopen the log file, if requested. - if (fReopenDebugLog) { - fReopenDebugLog = false; - fs::path pathDebug = GetDataDir() / "debug.log"; - if (fsbridge::freopen(pathDebug, "a", fileout) != nullptr) { - // unbuffered. - setbuf(fileout, nullptr); - } - } - - ret = FileWriteStr(strTimestamped, fileout); - } - } - return ret; -} - /** Interpret string as boolean, for argument parsing */ static bool InterpretBool(const std::string &strValue) { if (strValue.empty()) return true; @@ -742,31 +545,6 @@ #endif } -void ShrinkDebugFile() { - // Amount of debug.log to save at end when shrinking (must fit in memory) - constexpr size_t RECENT_DEBUG_HISTORY_SIZE = 10 * 1000000; - // Scroll debug.log if it's getting too big. - fs::path pathLog = GetDataDir() / "debug.log"; - FILE *file = fsbridge::fopen(pathLog, "r"); - // 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 && - fs::file_size(pathLog) > 11 * (RECENT_DEBUG_HISTORY_SIZE / 10)) { - // Restart the file with some of the end. - std::vector vch(RECENT_DEBUG_HISTORY_SIZE, 0); - fseek(file, -((long)vch.size()), SEEK_END); - int nBytes = fread(vch.data(), 1, vch.size(), file); - fclose(file); - - file = fsbridge::fopen(pathLog, "w"); - if (file) { - fwrite(vch.data(), 1, nBytes, file); - fclose(file); - } - } else if (file != nullptr) - fclose(file); -} - #ifdef WIN32 fs::path GetSpecialFolderPath(int nFolder, bool fCreate) { char pszPath[MAX_PATH] = "";