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/bitcoind.cpp b/src/bitcoind.cpp --- a/src/bitcoind.cpp +++ b/src/bitcoind.cpp @@ -15,6 +15,7 @@ #include "httprpc.h" #include "httpserver.h" #include "init.h" +#include "logging.h" #include "noui.h" #include "rpc/server.h" #include "scheduler.h" diff --git a/src/init.cpp b/src/init.cpp --- a/src/init.cpp +++ b/src/init.cpp @@ -21,6 +21,7 @@ #include "httprpc.h" #include "httpserver.h" #include "key.h" +#include "logging.h" #include "miner.h" #include "net.h" #include "net_processing.h" @@ -1232,6 +1233,11 @@ fLogTimeMicros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS); fLogIPs = gArgs.GetBoolArg("-logips", DEFAULT_LOGIPS); + g_logger.reset(new BCLog::Logger()); + g_logger->log_timestamps = fLogTimestamps; + g_logger->log_time_micros = fLogTimeMicros; + // TODO: logthreadid, loglevel + LogPrintf("\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n"); LogPrintf("%s version %s\n", CLIENT_NAME, FormatFullVersion()); } @@ -1368,6 +1374,8 @@ } // Step 3: parameter-to-internal-flags + uint32_t log_flags = 0; + if (gArgs.IsArgSet("-debug")) { // Special-case: if -debug=0/-nodebug is set, turn off debugging // messages @@ -1381,7 +1389,7 @@ strprintf(_("Unsupported logging category %s=%s."), "-debug", cat)); } - logCategories |= flag; + log_flags |= flag; } } } @@ -1394,10 +1402,14 @@ InitWarning(strprintf(_("Unsupported logging category %s=%s."), "-debugexclude", cat)); } - logCategories &= ~flag; + log_flags &= ~flag; } } + // Assign configured log categories to global logger. + logCategories.store(log_flags); + if (g_logger) g_logger->categories = static_cast(log_flags); + // Check for -debugnet if (gArgs.GetBoolArg("-debugnet", false)) InitWarning( @@ -2288,6 +2300,12 @@ SetRPCWarmupFinished(); uiInterface.InitMessage(_("Done loading")); + LOG(INFO, ALL).Message("Done with init %d", 5); + + LOG(INFO, NET) + .Message("There's net code happening") + .With("ip_address", "1.2.3.4"); + #ifdef ENABLE_WALLET for (CWalletRef pwallet : vpwallets) { pwallet->postInitProcess(scheduler); diff --git a/src/logging.h b/src/logging.h new file mode 100644 --- /dev/null +++ b/src/logging.h @@ -0,0 +1,104 @@ +// Copyright (c) 2018 The Bitcoin ABC 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 "tinyformat.h" +#include "univalue.h" +#include "util.h" + +namespace BCLog { + +class Logger; + +/** + * Levels represent the severity of log lines. Loggers only emit log lines + * with a level greater than the configured threshold. + */ +enum Level { DEBUG, INFO, WARN, ERROR, FATAL }; + +/** + * A structured log entry. The class is designed to be used within a macro. + * As such, it writes its contents to a Logger instance it its destructor. + * + * This class should not be accessed directly, only through the LOG macro. + */ +class LogLine { + friend Logger; + +private: + Logger *m_logger; + UniValue m_value; + +public: + explicit LogLine(Logger *logger, Level level, LogFlags category); + + LogLine() = delete; + LogLine(const LogLine &other) = delete; + LogLine(LogLine &&other) = delete; + + /// Destructor writes data to the logger if available. + ~LogLine(); + + /// Adds a primary message field with key "msg". + LogLine &Message(const std::string &message); + + /// Adds a key-value field to the log line. + LogLine &With(const std::string &key, const UniValue &val); + + template + LogLine &With(const std::string &key, const char *fmt, + const Args &... args) { + return With(key, tfm::format(fmt, args...)); + } + + template + LogLine &Message(const char *fmt, const Args &... args) { + return Message(tfm::format(fmt, args...)); + } +}; + +/** + * A Logger is used write structured log lines to an output channel. + */ +class Logger { +public: + bool log_timestamps = true; + bool log_time_micros = false; + bool log_thread_id = false; + + Level threshold_level = INFO; + LogFlags categories = NONE; + + bool WillWriteLevel(Level level) const; + bool WillWriteCategory(LogFlags category) const; + + void Write(const LogLine &log); +}; + +} // namespace BCLog + +extern std::unique_ptr g_logger; + +/** + * This macro is the primary method of logging data. Methods defined on + * BC::LogLine can be chained onto the resulting value. The With() method is + * used to add key-value entries to the structured log line. The level threshold + * and accepted categories are configured on the global logger instance. + * + * Example usage: + * + * LOG(INFO, ALL) + * .Message("New block was received") + * .With("height": 525318) + * .With("tx_count": 25); + */ +#define LOG(level, category) \ + if (g_logger && g_logger->WillWriteLevel(BCLog::level) && \ + g_logger->WillWriteCategory(BCLog::category)) \ + BCLog::LogLine(g_logger.get(), BCLog::level, BCLog::category) \ + .With("at", __func__) + +#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,137 @@ +// Copyright (c) 2018 The Bitcoin ABC 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 +#include +#include + +static std::string FormatTimestamp(bool include_micros) { + int64_t time_micros = GetLogTimeMicros(); + std::string formatted = + DateTimeStrFormat("%Y-%m-%d %H:%M:%S", time_micros / 1000000); + if (include_micros) { + formatted += strprintf(".%06d", time_micros % 1000000); + } + return formatted; +} + +static std::string FormatThreadID() { + std::stringstream ss; + ss << std::this_thread::get_id(); + return ss.str(); +} + +static std::string FormatLogLevel(BCLog::Level level) { + switch (level) { + case BCLog::DEBUG: + return "debug"; + case BCLog::INFO: + return "info"; + case BCLog::WARN: + return "warn"; + case BCLog::ERROR: + return "error"; + case BCLog::FATAL: + return "fatal"; + } + return "unknown"; +} + +static std::string FormatLogCategory(BCLog::LogFlags category) { + switch (category) { + case BCLog::NET: + return "net"; + case BCLog::TOR: + return "tor"; + case BCLog::MEMPOOL: + return "mempool"; + case BCLog::HTTP: + return "http"; + case BCLog::BENCH: + return "bench"; + case BCLog::ZMQ: + return "zmq"; + case BCLog::DB: + return "db"; + case BCLog::RPC: + return "rpc"; + case BCLog::ESTIMATEFEE: + return "estimatefee"; + case BCLog::ADDRMAN: + return "addrman"; + case BCLog::SELECTCOINS: + return "selectcoins"; + case BCLog::REINDEX: + return "reindex"; + case BCLog::CMPCTBLOCK: + return "cmpctblock"; + case BCLog::RAND: + return "rand"; + case BCLog::PRUNE: + return "prune"; + case BCLog::PROXY: + return "proxy"; + case BCLog::MEMPOOLREJ: + return "mempoolrej"; + case BCLog::LIBEVENT: + return "libevent"; + case BCLog::COINDB: + return "coindb"; + case BCLog::QT: + return "qt"; + case BCLog::LEVELDB: + return "leveldb"; + + case BCLog::ALL:; + case BCLog::NONE:; + } + return ""; +} + +BCLog::LogLine::LogLine(BCLog::Logger *logger, BCLog::Level level, + BCLog::LogFlags category) + : m_logger(logger), m_value(UniValue::VOBJ) { + if (!m_logger) return; + + if (m_logger->log_timestamps) { + With("timestamp", FormatTimestamp(m_logger->log_time_micros)); + } + With("level", FormatLogLevel(level)); + if (category != BCLog::ALL) { + With("category", FormatLogCategory(category)); + } + if (m_logger->log_thread_id) { + With("thread_id", FormatThreadID()); + } +} + +BCLog::LogLine::~LogLine() { + if (m_logger) m_logger->Write(*this); +} + +BCLog::LogLine &BCLog::LogLine::Message(const std::string &message) { + return With("msg", message); +} + +BCLog::LogLine &BCLog::LogLine::With(const std::string &key, + const UniValue &val) { + m_value.pushKV(key, val); + return *this; +} + +bool BCLog::Logger::WillWriteLevel(Level level) const { + return level >= threshold_level; +} + +bool BCLog::Logger::WillWriteCategory(LogFlags category) const { + return category == BCLog::ALL || (categories & category) != 0; +} + +void BCLog::Logger::Write(const LogLine &log) { + std::cout << log.m_value.write() << std::endl; +} + +std::unique_ptr g_logger;