logging.h

Go to the documentation of this file.

// 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.
 
#ifndef BITCOIN_LOGGING_H
#define BITCOIN_LOGGING_H
 
#include <crypto/siphash.h>
#include <span.h>
#include <threadsafety.h>
#include <tinyformat.h>
#include <util/fs.h>
#include <util/string.h>
#include <util/time.h>
 
#include <atomic>
#include <cstdint>
#include <cstring>
#include <functional>
#include <list>
#include <memory>
#include <mutex>
#include <source_location>
#include <string>
#include <unordered_map>
#include <unordered_set>
#include <vector>
 
static const bool DEFAULT_LOGTIMEMICROS = false;
static const bool DEFAULT_LOGIPS = false;
static const bool DEFAULT_LOGTIMESTAMPS = true;
static const bool DEFAULT_LOGTHREADNAMES = false;
static const bool DEFAULT_LOGSOURCELOCATIONS = false;
static constexpr bool DEFAULT_LOGLEVELALWAYS = false;
 
extern bool fLogIPs;
extern const char *const DEFAULT_DEBUGLOGFILE;
 
struct SourceLocationEqual {
    bool operator()(const std::source_location &lhs,
                    const std::source_location &rhs) const noexcept {
        return lhs.line() == rhs.line() &&
               std::string_view(lhs.file_name()) ==
                   std::string_view(rhs.file_name());
    }
};
 
struct SourceLocationHasher {
    size_t operator()(const std::source_location &s) const noexcept {
        // Use CSipHasher(0, 0) as a simple way to get uniform distribution.
        return size_t(CSipHasher(0, 0)
                          .Write(s.line())
                          .Write(MakeUCharSpan(std::string_view{s.file_name()}))
                          .Finalize());
    }
};
 
struct LogCategory {
    std::string category;
    bool active;
};
 
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),
    WALLETDB = (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),
    VALIDATION = (1 << 21),
    AVALANCHE = (1 << 22),
    I2P = (1 << 23),
    CHRONIK = (1 << 24),
#ifdef DEBUG_LOCKCONTENTION
    LOCK = (1 << 25),
#endif
    BLOCKSTORE = (1 << 26),
    NETDEBUG = (1 << 27),
    TXPACKAGES = (1 << 28),
    ALL = ~uint32_t(0),
};
 
enum class Level {
    // High-volume or detailed logging for development/debugging
    Trace = 0,
    // Reasonably noisy logging, but still usable in production
    Debug,
    // Default
    Info,
    Warning,
    Error,
};
constexpr auto DEFAULT_LOG_LEVEL{Level::Debug};
// buffer up to 1MB of log data prior to StartLogging
constexpr size_t DEFAULT_MAX_LOG_BUFFER{1'000'000};
// maximum number of bytes per source location that can be logged within the
// RATELIMIT_WINDOW
constexpr uint64_t RATELIMIT_MAX_BYTES{1024 * 1024};
// time window after which log ratelimit stats are reset
constexpr auto RATELIMIT_WINDOW{1h};
constexpr bool DEFAULT_LOGRATELIMIT{true};
 
class LogRateLimiter {
public:
    struct Stats {
        uint64_t m_available_bytes;
        uint64_t m_dropped_bytes{0};
 
        Stats(uint64_t max_bytes) : m_available_bytes{max_bytes} {}
        bool Consume(uint64_t bytes);
    };
 
private:
    mutable StdMutex m_mutex;
 
    std::unordered_map<std::source_location, Stats, SourceLocationHasher,
                       SourceLocationEqual>
        m_source_locations GUARDED_BY(m_mutex);
    std::atomic<bool> m_suppression_active{false};
    LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
 
public:
    using SchedulerFunction =
        std::function<void(std::function<bool()>, std::chrono::milliseconds)>;
    static std::shared_ptr<LogRateLimiter>
    Create(SchedulerFunction &&scheduler_func, uint64_t max_bytes,
           std::chrono::seconds reset_window);
    const uint64_t m_max_bytes;
    const std::chrono::seconds m_reset_window;
    enum class Status {
        // string fits within the limit
        UNSUPPRESSED,
        // suppression has started since this string
        NEWLY_SUPPRESSED,
        // suppression is still ongoing
        STILL_SUPPRESSED,
    };
    [[nodiscard]] Status Consume(const std::source_location &source_loc,
                                 const std::string &str)
        EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
    void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
    bool SuppressionsActive() const { return m_suppression_active; }
};
 
class Logger {
public:
    struct BufferedLog {
        SystemClock::time_point now;
        std::chrono::seconds mocktime;
        std::string str, threadname;
        std::source_location source_loc;
        LogFlags category;
        Level level;
    };
 
private:
    // Can not use Mutex from sync.h because in debug mode it would cause a
    // deadlock when a potential deadlock was detected
    mutable StdMutex m_cs;
 
    FILE *m_fileout GUARDED_BY(m_cs) = nullptr;
    std::list<BufferedLog> m_msgs_before_open GUARDED_BY(m_cs);
    bool m_buffering GUARDED_BY(m_cs) = true;
    size_t m_max_buffer_memusage GUARDED_BY(m_cs){DEFAULT_MAX_LOG_BUFFER};
    size_t m_cur_buffer_memusage GUARDED_BY(m_cs){0};
    size_t m_buffer_lines_discarded GUARDED_BY(m_cs){0};
 
    std::atomic_bool m_started_new_line{true};
 
    std::shared_ptr<LogRateLimiter> m_limiter GUARDED_BY(m_cs);
 
    std::unordered_map<LogFlags, Level> m_category_log_levels GUARDED_BY(m_cs);
 
    std::atomic<Level> m_log_level{DEFAULT_LOG_LEVEL};
 
    std::atomic<uint32_t> m_categories{0};
 
    void FormatLogStrInPlace(std::string &str, LogFlags category, Level level,
                             const std::source_location &source_loc,
                             std::string_view threadname,
                             SystemClock::time_point now,
                             std::chrono::seconds mocktime) const;
 
    std::string LogTimestampStr(SystemClock::time_point now,
                                std::chrono::seconds mocktime) const;
 
    std::list<std::function<void(const std::string &)>>
        m_print_callbacks GUARDED_BY(m_cs){};
 
    void LogPrintStr_(std::string_view str, std::source_location &&source_loc,
                      BCLog::LogFlags category, BCLog::Level level,
                      bool should_ratelimit) EXCLUSIVE_LOCKS_REQUIRED(m_cs);
 
public:
    bool m_print_to_console = false;
    bool m_print_to_file = false;
 
    bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS;
    bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
    bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
    bool m_log_sourcelocations = DEFAULT_LOGSOURCELOCATIONS;
    bool m_always_print_category_level = DEFAULT_LOGLEVELALWAYS;
 
    fs::path m_file_path;
    std::atomic<bool> m_reopen_file{false};
 
    std::string GetLogPrefix(LogFlags category, Level level) const;
 
    ~Logger();
 
    void LogPrintStr(std::string_view str, std::source_location &&source_loc,
                     BCLog::LogFlags category, BCLog::Level level,
                     bool should_ratelimit);
 
    bool Enabled() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs) {
        StdLockGuard scoped_lock(m_cs);
        return m_buffering || m_print_to_console || m_print_to_file ||
               !m_print_callbacks.empty();
    }
 
    std::list<std::function<void(const std::string &)>>::iterator
    PushBackCallback(std::function<void(const std::string &)> fun)
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs) {
        StdLockGuard scoped_lock(m_cs);
        m_print_callbacks.push_back(std::move(fun));
        return --m_print_callbacks.end();
    }
 
    void DeleteCallback(
        std::list<std::function<void(const std::string &)>>::iterator it)
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs) {
        StdLockGuard scoped_lock(m_cs);
        m_print_callbacks.erase(it);
    }
 
    bool StartLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
    void DisconnectTestLogger() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
 
    void DisableLogging() EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
 
    void SetRateLimiting(std::shared_ptr<LogRateLimiter> limiter)
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs) {
        StdLockGuard scoped_lock(m_cs);
        m_limiter = std::move(limiter);
    }
 
    void ShrinkDebugFile();
 
    std::unordered_map<LogFlags, Level> CategoryLevels() const
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs) {
        StdLockGuard scoped_lock(m_cs);
        return m_category_log_levels;
    }
    void SetCategoryLogLevel(const std::unordered_map<LogFlags, Level> &levels)
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs) {
        StdLockGuard scoped_lock(m_cs);
        m_category_log_levels = levels;
    }
    bool SetCategoryLogLevel(std::string_view category_str,
                             std::string_view level_str)
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
 
    Level LogLevel() const { return m_log_level.load(); }
    void SetLogLevel(Level level) { m_log_level = level; }
    bool SetLogLevel(std::string_view level);
 
    uint32_t GetCategoryMask() const { return m_categories.load(); }
 
    void EnableCategory(LogFlags category);
    bool EnableCategory(std::string_view str);
    void DisableCategory(LogFlags category);
    bool DisableCategory(std::string_view str);
 
    bool WillLogCategory(LogFlags category) const;
    bool WillLogCategoryLevel(LogFlags category, Level level) const
        EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
 
    std::vector<LogCategory> LogCategoriesList() const;
    std::string LogCategoriesString() const {
        return Join(LogCategoriesList(), ", ",
                    [&](const LogCategory &i) { return i.category; });
    };
 
    std::string LogLevelsString() const;
 
    static std::string LogLevelToStr(BCLog::Level level);
 
    bool DefaultShrinkDebugFile() const;
};
 
} // namespace BCLog
 
BCLog::Logger &LogInstance();
 
static inline bool LogAcceptCategory(BCLog::LogFlags category,
                                     BCLog::Level level) {
    return LogInstance().WillLogCategoryLevel(category, level);
}
 
bool GetLogCategory(BCLog::LogFlags &flag, std::string_view str);
 
// Be conservative when using LogPrintf/error or other things which
// unconditionally log to debug.log! It should not be the case that an inbound
// peer can fill up a user's disk with debug.log entries.
template <typename... Args>
static inline void LogPrintf_(std::source_location &&source_loc,
                              BCLog::LogFlags flag, BCLog::Level level,
                              bool should_ratelimit, const char *fmt,
                              const Args &...args) {
    if (LogInstance().Enabled()) {
        std::string log_msg;
        try {
            log_msg = tfm::format(fmt, args...);
        } catch (tinyformat::format_error &fmterr) {
            log_msg = "Error \"" + std::string(fmterr.what()) +
                      "\" while formatting log message: " + fmt;
        }
        LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level,
                                  should_ratelimit);
    }
}
 
#define LogPrintLevel_(category, level, should_ratelimit, ...)                 \
    LogPrintf_(std::source_location::current(), category, level,               \
               should_ratelimit, __VA_ARGS__)
 
// Log unconditionally. Uses basic rate limiting to mitigate disk filling
// attacks.
#define LogInfo(...)                                                           \
    LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Info,                   \
                   /*should_ratelimit=*/true, __VA_ARGS__)
#define LogWarning(...)                                                        \
    LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Warning,                \
                   /*should_ratelimit=*/true, __VA_ARGS__)
#define LogError(...)                                                          \
    LogPrintLevel_(BCLog::LogFlags::ALL, BCLog::Level::Error,                  \
                   /*should_ratelimit=*/true, __VA_ARGS__)
 
// Deprecated unconditional logging.
#define LogPrintf(...) LogInfo(__VA_ARGS__)
 
// Use a macro instead of a function for conditional logging to prevent
// evaluating arguments when logging for the category is not enabled.
 
// Log by prefixing the output with the passed category name and severity level.
// This can either log conditionally if the category is allowed or
// unconditionally if level >= BCLog::Level::Info is passed. If this function
// logs unconditionally, logging to disk is rate-limited. This is important so
// that callers don't need to worry about accidentally introducing a disk-fill
// vulnerability if level >= Info is used. Additionally, users specifying -debug
// are assumed to be developers or power users who are aware that -debug may
// cause excessive disk usage due to logging.
#define LogPrintLevel(category, level, ...)                                    \
    do {                                                                       \
        if (LogAcceptCategory((category), (level))) {                          \
            bool rate_limit{level >= BCLog::Level::Info};                      \
            LogPrintLevel_(category, level, rate_limit, __VA_ARGS__);          \
        }                                                                      \
    } while (0)
 
// Log conditionally, prefixing the output with the passed category name.
#define LogDebug(category, ...)                                                \
    LogPrintLevel(category, BCLog::Level::Debug, __VA_ARGS__)
#define LogTrace(category, ...)                                                \
    LogPrintLevel(category, BCLog::Level::Trace, __VA_ARGS__)
 
// Deprecated conditional logging
#define LogPrint(category, ...) LogDebug(category, __VA_ARGS__)
 
#define LogPrintfToBeContinued LogPrintf
#define LogPrintToBeContinued LogPrint
#define LogPrintLevelToBeContinued LogPrintLevel
 
#endif // BITCOIN_LOGGING_H