diff --git a/src/logging.cpp b/src/logging.cpp index 60e8f969b..b3dcd7262 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -1,265 +1,271 @@ // 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 "utiltime.h" bool fLogIPs = DEFAULT_LOGIPS; const char *const DEFAULT_DEBUGLOGFILE = "debug.log"; /** * 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. * * This method of initialization was originally introduced in * ee3374234c60aba2cc4c5cd5cac1c0aefc2d817c. */ BCLog::Logger &GetLogger() { static BCLog::Logger *const logger = new BCLog::Logger(); return *logger; } static int FileWriteStr(const std::string &str, FILE *fp) { return fwrite(str.data(), 1, str.size(), fp); } fs::path BCLog::Logger::GetDebugLogPath() { fs::path logfile(gArgs.GetArg("-debuglogfile", DEFAULT_DEBUGLOGFILE)); if (logfile.is_absolute()) { return logfile; } else { return GetDataDir() / logfile; } } bool BCLog::Logger::OpenDebugLog() { std::lock_guard scoped_lock(m_file_mutex); assert(m_fileout == nullptr); fs::path pathDebug = GetDebugLogPath(); m_fileout = fsbridge::fopen(pathDebug, "a"); if (!m_fileout) { return false; } // Unbuffered. setbuf(m_fileout, nullptr); // Dump buffered messages from before we opened the log. while (!m_msgs_before_open.empty()) { FileWriteStr(m_msgs_before_open.front(), m_fileout); m_msgs_before_open.pop_front(); } return true; } 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::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; } 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 = GetLogTimeMicros(); + int64_t nTimeMicros = GetTimeMicros(); strStamped = DateTimeStrFormat("%Y-%m-%d %H:%M:%S", nTimeMicros / 1000000); if (m_log_time_micros) { strStamped += strprintf(".%06d", nTimeMicros % 1000000); } + int64_t mocktime = GetMockTime(); + if (mocktime) { + strStamped += " (mocktime: " + + DateTimeStrFormat("%Y-%m-%d %H:%M:%S", mocktime) + + ")"; + } strStamped += ' ' + str; } else { strStamped = str; } if (!str.empty() && str[str.size() - 1] == '\n') { m_started_new_line = true; } else { m_started_new_line = false; } return strStamped; } int BCLog::Logger::LogPrintStr(const std::string &str) { // Returns total number of characters written. int ret = 0; std::string strTimestamped = LogTimestampStr(str); if (m_print_to_console) { // Print to console. ret = fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout); fflush(stdout); } else if (m_print_to_file) { std::lock_guard scoped_lock(m_file_mutex); // Buffer if we haven't opened the log yet. if (m_fileout == nullptr) { ret = strTimestamped.length(); m_msgs_before_open.push_back(strTimestamped); } else { // Reopen the log file, if requested. if (m_reopen_file) { m_reopen_file = false; fs::path pathDebug = GetDebugLogPath(); if (fsbridge::freopen(pathDebug, "a", m_fileout) != nullptr) { // unbuffered. setbuf(m_fileout, nullptr); } } ret = FileWriteStr(strTimestamped, m_fileout); } } return ret; } 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; // Scroll debug.log if it's getting too big. fs::path pathLog = GetDebugLogPath(); 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); } } 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/utiltime.cpp b/src/utiltime.cpp index 99c2de850..61fa238c6 100644 --- a/src/utiltime.cpp +++ b/src/utiltime.cpp @@ -1,77 +1,71 @@ // Copyright (c) 2009-2010 Satoshi Nakamoto // Copyright (c) 2009-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. #if defined(HAVE_CONFIG_H) #include "config/bitcoin-config.h" #endif #include "utiltime.h" #include #include #include //!< For unit testing static std::atomic nMockTime(0); int64_t GetTime() { int64_t mocktime = nMockTime.load(std::memory_order_relaxed); if (mocktime) { return mocktime; } time_t now = time(nullptr); assert(now > 0); return now; } void SetMockTime(int64_t nMockTimeIn) { nMockTime.store(nMockTimeIn, std::memory_order_relaxed); } +int64_t GetMockTime() { + return nMockTime.load(std::memory_order_relaxed); +} + int64_t GetTimeMillis() { int64_t now = (boost::posix_time::microsec_clock::universal_time() - boost::posix_time::ptime(boost::gregorian::date(1970, 1, 1))) .total_milliseconds(); assert(now > 0); return now; } int64_t GetTimeMicros() { int64_t now = (boost::posix_time::microsec_clock::universal_time() - boost::posix_time::ptime(boost::gregorian::date(1970, 1, 1))) .total_microseconds(); assert(now > 0); return now; } int64_t GetSystemTimeInSeconds() { return GetTimeMicros() / 1000000; } -/** Return a time useful for the debug log */ -int64_t GetLogTimeMicros() { - int64_t mocktime = nMockTime.load(std::memory_order_relaxed); - if (mocktime) { - return mocktime * 1000000; - } - - return GetTimeMicros(); -} - void MilliSleep(int64_t n) { boost::this_thread::sleep_for(boost::chrono::milliseconds(n)); } std::string DateTimeStrFormat(const char *pszFormat, int64_t nTime) { static std::locale classic(std::locale::classic()); // std::locale takes ownership of the pointer std::locale loc(classic, new boost::posix_time::time_facet(pszFormat)); std::stringstream ss; ss.imbue(loc); ss << boost::posix_time::from_time_t(nTime); return ss.str(); } diff --git a/src/utiltime.h b/src/utiltime.h index 5ca3cc17c..f927ffc6b 100644 --- a/src/utiltime.h +++ b/src/utiltime.h @@ -1,33 +1,33 @@ // Copyright (c) 2009-2010 Satoshi Nakamoto // Copyright (c) 2009-2015 The Bitcoin Core developers // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. #ifndef BITCOIN_UTILTIME_H #define BITCOIN_UTILTIME_H #include #include /** * GetTimeMicros() and GetTimeMillis() both return the system time, but in * different units. GetTime() returns the sytem time in seconds, but also * supports mocktime, where the time can be specified by the user, eg for * testing (eg with the setmocktime rpc, or -mocktime argument). * * TODO: Rework these functions to be type-safe (so that we don't inadvertently * compare numbers with different units, or compare a mocktime to system time). */ int64_t GetTime(); int64_t GetTimeMillis(); int64_t GetTimeMicros(); // Like GetTime(), but not mockable int64_t GetSystemTimeInSeconds(); -int64_t GetLogTimeMicros(); void SetMockTime(int64_t nMockTimeIn); +int64_t GetMockTime(); void MilliSleep(int64_t n); std::string DateTimeStrFormat(const char *pszFormat, int64_t nTime); #endif // BITCOIN_UTILTIME_H