logging.cpp

Go to the documentation of this file.

// Copyright (c) 2009-2010 Satoshi Nakamoto
// Copyright (c) 2009-present 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 <logging.h>
#include <memusage.h>
#include <util/check.h>
#include <util/fs.h>
#include <util/string.h>
#include <util/threadnames.h>
#include <util/time.h>
 
#include <array>
#include <cstring>
#include <map>
#include <optional>
#include <utility>
 
using util::Join;
using util::RemovePrefixView;
 
const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
constexpr auto MAX_USER_SETABLE_SEVERITY_LEVEL{BCLog::Level::Info};
 
BCLog::Logger& LogInstance()
{
    static BCLog::Logger* g_logger{new BCLog::Logger()};
    return *g_logger;
}
 
bool fLogIPs = DEFAULT_LOGIPS;
 
static int FileWriteStr(std::string_view str, FILE *fp)
{
    return fwrite(str.data(), 1, str.size(), fp);
}
 
bool BCLog::Logger::StartLogging()
{
    STDLOCK(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;
        }
 
        setbuf(m_fileout, nullptr); // unbuffered
 
        // 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;
    if (m_buffer_lines_discarded > 0) {
        LogPrint_({
            .category = BCLog::ALL,
            .level = Level::Info,
            .should_ratelimit = false,
            .source_loc = SourceLocation{__func__},
            .message = strprintf("Early logging buffer overflowed, %d log lines discarded.", m_buffer_lines_discarded),
        });
    }
    while (!m_msgs_before_open.empty()) {
        const auto& buflog = m_msgs_before_open.front();
        std::string s{Format(buflog)};
        m_msgs_before_open.pop_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_cur_buffer_memusage = 0;
    if (m_print_to_console) fflush(stdout);
 
    return true;
}
 
void BCLog::Logger::DisconnectTestLogger()
{
    STDLOCK(m_cs);
    m_buffering = true;
    if (m_fileout != nullptr) fclose(m_fileout);
    m_fileout = nullptr;
    m_print_callbacks.clear();
    m_max_buffer_memusage = DEFAULT_MAX_LOG_BUFFER;
    m_cur_buffer_memusage = 0;
    m_buffer_lines_discarded = 0;
    m_msgs_before_open.clear();
}
 
void BCLog::Logger::DisableLogging()
{
    {
        STDLOCK(m_cs);
        assert(m_buffering);
        assert(m_print_callbacks.empty());
    }
    m_print_to_file = false;
    m_print_to_console = false;
    StartLogging();
}
 
void BCLog::Logger::EnableCategory(BCLog::LogFlags flag)
{
    m_categories |= flag;
}
 
bool BCLog::Logger::EnableCategory(std::string_view str)
{
    if (const auto flag{GetLogCategory(str)}) {
        EnableCategory(*flag);
        return true;
    }
    return false;
}
 
void BCLog::Logger::DisableCategory(BCLog::LogFlags flag)
{
    m_categories &= ~flag;
}
 
bool BCLog::Logger::DisableCategory(std::string_view str)
{
    if (const auto flag{GetLogCategory(str)}) {
        DisableCategory(*flag);
        return true;
    }
    return false;
}
 
bool BCLog::Logger::WillLogCategory(BCLog::LogFlags category) const
{
    return (m_categories.load(std::memory_order_relaxed) & category) != 0;
}
 
bool BCLog::Logger::WillLogCategoryLevel(BCLog::LogFlags category, BCLog::Level level) const
{
    // Log messages at Info, Warning and Error level unconditionally, so that
    // important troubleshooting information doesn't get lost.
    if (level >= BCLog::Level::Info) return true;
 
    if (!WillLogCategory(category)) return false;
 
    STDLOCK(m_cs);
    const auto it{m_category_log_levels.find(category)};
    return level >= (it == m_category_log_levels.end() ? LogLevel() : it->second);
}
 
bool BCLog::Logger::DefaultShrinkDebugFile() const
{
    return m_categories == BCLog::NONE;
}
 
static const std::map<std::string, BCLog::LogFlags, std::less<>> LOG_CATEGORIES_BY_STR{
    {"net", BCLog::NET},
    {"tor", BCLog::TOR},
    {"mempool", BCLog::MEMPOOL},
    {"http", BCLog::HTTP},
    {"bench", BCLog::BENCH},
    {"zmq", BCLog::ZMQ},
    {"walletdb", BCLog::WALLETDB},
    {"rpc", BCLog::RPC},
    {"estimatefee", BCLog::ESTIMATEFEE},
    {"addrman", BCLog::ADDRMAN},
    {"selectcoins", BCLog::SELECTCOINS},
    {"reindex", BCLog::REINDEX},
    {"cmpctblock", BCLog::CMPCTBLOCK},
    {"rand", BCLog::RAND},
    {"prune", BCLog::PRUNE},
    {"proxy", BCLog::PROXY},
    {"mempoolrej", BCLog::MEMPOOLREJ},
    {"coindb", BCLog::COINDB},
    {"qt", BCLog::QT},
    {"leveldb", BCLog::LEVELDB},
    {"validation", BCLog::VALIDATION},
    {"i2p", BCLog::I2P},
    {"ipc", BCLog::IPC},
#ifdef DEBUG_LOCKCONTENTION
    {"lock", BCLog::LOCK},
#endif
    {"blockstorage", BCLog::BLOCKSTORAGE},
    {"txreconciliation", BCLog::TXRECONCILIATION},
    {"scan", BCLog::SCAN},
    {"txpackages", BCLog::TXPACKAGES},
    {"kernel", BCLog::KERNEL},
    {"privatebroadcast", BCLog::PRIVBROADCAST},
    {"mining", BCLog::MINING},
};
 
static const std::unordered_map<BCLog::LogFlags, std::string> LOG_CATEGORIES_BY_FLAG{
    // Swap keys and values from LOG_CATEGORIES_BY_STR.
    [](const auto& in) {
        std::unordered_map<BCLog::LogFlags, std::string> out;
        for (const auto& [k, v] : in) {
            const bool inserted{out.emplace(v, k).second};
            assert(inserted);
        }
        return out;
    }(LOG_CATEGORIES_BY_STR)
};
 
std::optional<BCLog::LogFlags> BCLog::Logger::GetLogCategory(std::string_view str)
{
    if (str.empty() || str == "1" || str == "all") {
        return BCLog::ALL;
    }
    auto it = LOG_CATEGORIES_BY_STR.find(str);
    if (it != LOG_CATEGORIES_BY_STR.end()) {
        return it->second;
    }
    if (str == "libevent") {
       LogWarning("The logging category `%s` is deprecated, does nothing, and will be removed in a future version", str);
       return BCLog::NONE;
    }
    return std::nullopt;
}
 
std::string BCLog::Logger::LogLevelToStr(BCLog::Level level)
{
    switch (level) {
    case BCLog::Level::Trace:
        return "trace";
    case BCLog::Level::Debug:
        return "debug";
    case BCLog::Level::Info:
        return "info";
    case BCLog::Level::Warning:
        return "warning";
    case BCLog::Level::Error:
        return "error";
    }
    assert(false);
}
 
static std::string LogCategoryToStr(BCLog::LogFlags category)
{
    if (category == BCLog::ALL) {
        return "all";
    }
    auto it = LOG_CATEGORIES_BY_FLAG.find(category);
    assert(it != LOG_CATEGORIES_BY_FLAG.end());
    return it->second;
}
 
static std::optional<BCLog::Level> GetLogLevel(std::string_view level_str)
{
    if (level_str == "trace") {
        return BCLog::Level::Trace;
    } else if (level_str == "debug") {
        return BCLog::Level::Debug;
    } else if (level_str == "info") {
        return BCLog::Level::Info;
    } else if (level_str == "warning") {
        return BCLog::Level::Warning;
    } else if (level_str == "error") {
        return BCLog::Level::Error;
    } else {
        return std::nullopt;
    }
}
 
std::vector<LogCategory> BCLog::Logger::LogCategoriesList() const
{
    std::vector<LogCategory> ret;
    ret.reserve(LOG_CATEGORIES_BY_STR.size());
    for (const auto& [category, flag] : LOG_CATEGORIES_BY_STR) {
        ret.push_back(LogCategory{.category = category, .active = WillLogCategory(flag)});
    }
    return ret;
}

static constexpr std::array<BCLog::Level, 3> LogLevelsList()
{
    return {BCLog::Level::Info, BCLog::Level::Debug, BCLog::Level::Trace};
}
 
std::string BCLog::Logger::LogLevelsString() const
{
    const auto& levels = LogLevelsList();
    return Join(std::vector<BCLog::Level>{levels.begin(), levels.end()}, ", ", [](BCLog::Level level) { return LogLevelToStr(level); });
}
 
std::string BCLog::Logger::LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const
{
    std::string strStamped;
 
    if (!m_log_timestamps)
        return strStamped;
 
    const auto now_seconds{std::chrono::time_point_cast<std::chrono::seconds>(now)};
    strStamped = FormatISO8601DateTime(TicksSinceEpoch<std::chrono::seconds>(now_seconds));
    if (m_log_time_micros && !strStamped.empty()) {
        strStamped.pop_back();
        strStamped += strprintf(".%06dZ", Ticks<std::chrono::microseconds>(now - now_seconds));
    }
    if (mocktime > 0s) {
        strStamped += " (mocktime: " + FormatISO8601DateTime(count_seconds(mocktime)) + ")";
    }
    strStamped += ' ';
 
    return strStamped;
}
 
namespace BCLog {
    std::string LogEscapeMessage(std::string_view 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
 
std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level level) const
{
    if (category == LogFlags::NONE) category = LogFlags::ALL;
 
    const bool has_category{m_always_print_category_level || category != LogFlags::ALL};
 
    // If there is no category, Info is implied
    if (!has_category && level == Level::Info) return {};
 
    std::string s{"["};
    if (has_category) {
        s += LogCategoryToStr(category);
    }
 
    if (m_always_print_category_level || !has_category || level != Level::Debug) {
        // If there is a category, Debug is implied, so don't add the level
 
        // Only add separator if we have a category
        if (has_category) s += ":";
        s += Logger::LogLevelToStr(level);
    }
 
    s += "] ";
    return s;
}
 
static size_t MemUsage(const util::log::Entry& log)
{
    return memusage::DynamicUsage(log.message) +
           memusage::DynamicUsage(log.thread_name) +
           memusage::MallocUsage(sizeof(memusage::list_node<util::log::Entry>));
}
 
BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window)
    : m_max_bytes{max_bytes}, m_reset_window{reset_window} {}
 
std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
    SchedulerFunction&& scheduler_func, uint64_t max_bytes, std::chrono::seconds reset_window)
{
    auto limiter{std::shared_ptr<LogRateLimiter>(new LogRateLimiter(max_bytes, reset_window))};
    std::weak_ptr<LogRateLimiter> weak_limiter{limiter};
    auto reset = [weak_limiter] {
        if (auto shared_limiter{weak_limiter.lock()}) shared_limiter->Reset();
    };
    scheduler_func(reset, limiter->m_reset_window);
    return limiter;
}
 
BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
    const SourceLocation& source_loc,
    const std::string& str)
{
    STDLOCK(m_mutex);
    auto& stats{m_source_locations.try_emplace(source_loc, m_max_bytes).first->second};
    Status status{stats.m_dropped_bytes > 0 ? Status::STILL_SUPPRESSED : Status::UNSUPPRESSED};
 
    if (!stats.Consume(str.size()) && status == Status::UNSUPPRESSED) {
        status = Status::NEWLY_SUPPRESSED;
        m_suppression_active = true;
    }
 
    return status;
}
 
std::string BCLog::Logger::Format(const util::log::Entry& entry) const
{
    std::string result{LogTimestampStr(entry.timestamp, entry.mocktime)};
 
    if (m_log_threadnames) {
        result += strprintf("[%s] ", (entry.thread_name.empty() ? "unknown" : entry.thread_name));
    }
 
    if (m_log_sourcelocations) {
        result += strprintf("[%s:%d] [%s] ", RemovePrefixView(entry.source_loc.file_name(), "./"), entry.source_loc.line(), entry.source_loc.function_name_short());
    }
 
    result += GetLogPrefix(static_cast<LogFlags>(entry.category), entry.level);
    result += LogEscapeMessage(entry.message);
 
    if (!result.ends_with('\n')) result += '\n';
    return result;
}
 
void BCLog::Logger::LogPrint(util::log::Entry entry)
{
    STDLOCK(m_cs);
    return LogPrint_(std::move(entry));
}
 
// NOLINTNEXTLINE(misc-no-recursion)
void BCLog::Logger::LogPrint_(util::log::Entry entry)
{
    if (m_buffering) {
        {
            m_cur_buffer_memusage += MemUsage(entry);
            m_msgs_before_open.push_back(std::move(entry));
        }
 
        while (m_cur_buffer_memusage > m_max_buffer_memusage) {
            if (m_msgs_before_open.empty()) {
                m_cur_buffer_memusage = 0;
                break;
            }
            m_cur_buffer_memusage -= MemUsage(m_msgs_before_open.front());
            m_msgs_before_open.pop_front();
            ++m_buffer_lines_discarded;
        }
 
        return;
    }
 
    std::string str_prefixed{Format(entry)};
    bool ratelimit{false};
    if (entry.should_ratelimit && m_limiter) {
        auto status{m_limiter->Consume(entry.source_loc, str_prefixed)};
        if (status == LogRateLimiter::Status::NEWLY_SUPPRESSED) {
            // NOLINTNEXTLINE(misc-no-recursion)
            LogPrint_({
                .category = LogFlags::ALL,
                .level = Level::Warning,
                .should_ratelimit = false, // with should_ratelimit=false, this cannot lead to infinite recursion
                .source_loc = SourceLocation{__func__},
                .message = strprintf(
                    "Excessive logging detected from %s:%d (%s): >%d bytes logged during "
                    "the last time window of %is. Suppressing logging to disk from this "
                    "source location until time window resets. Console logging "
                    "unaffected. Last log entry.",
                    entry.source_loc.file_name(), entry.source_loc.line(), entry.source_loc.function_name_short(),
                    m_limiter->m_max_bytes,
                    Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
            });
        } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
            ratelimit = true;
        }
    }
 
    // To avoid confusion caused by dropped log messages when debugging an issue,
    // we prefix log lines with "[*]" when there are any suppressed source locations.
    if (m_limiter && m_limiter->SuppressionsActive()) {
        str_prefixed.insert(0, "[*] ");
    }
 
    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 && !ratelimit) {
        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) {
                setbuf(new_fileout, nullptr); // unbuffered
                fclose(m_fileout);
                m_fileout = new_fileout;
            }
        }
        FileWriteStr(str_prefixed, m_fileout);
    }
}
 
void BCLog::Logger::ShrinkDebugFile()
{
    STDLOCK(m_cs);
 
    // 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<char> vch(RECENT_DEBUG_HISTORY_SIZE, 0);
        if (fseek(file, -((long)vch.size()), SEEK_END)) {
            // LogWarning, except with m_cs held
            LogPrint_({
                .category = BCLog::ALL,
                .level = Level::Warning,
                .should_ratelimit = true,
                .source_loc = SourceLocation{__func__},
                .message = "Failed to shrink debug log file: fseek(...) failed",
            });
            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::LogRateLimiter::Reset()
{
    decltype(m_source_locations) source_locations;
    {
        STDLOCK(m_mutex);
        source_locations.swap(m_source_locations);
        m_suppression_active = false;
    }
    for (const auto& [source_loc, stats] : source_locations) {
        if (stats.m_dropped_bytes == 0) continue;
        LogWarning(util::log::NO_RATE_LIMIT,
            "Restarting logging from %s:%d (%s): %d bytes were dropped during the last %ss.",
            source_loc.file_name(), source_loc.line(), source_loc.function_name_short(),
            stats.m_dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
    }
}
 
bool BCLog::LogRateLimiter::Stats::Consume(uint64_t bytes)
{
    if (bytes > m_available_bytes) {
        m_dropped_bytes += bytes;
        m_available_bytes = 0;
        return false;
    }
 
    m_available_bytes -= bytes;
    return true;
}
 
bool BCLog::Logger::SetLogLevel(std::string_view level_str)
{
    const auto level = GetLogLevel(level_str);
    if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
    m_log_level = level.value();
    return true;
}
 
bool BCLog::Logger::SetCategoryLogLevel(std::string_view category_str, std::string_view level_str)
{
    const auto flag{GetLogCategory(category_str)};
    if (!flag) return false;
 
    const auto level = GetLogLevel(level_str);
    if (!level.has_value() || level.value() > MAX_USER_SETABLE_SEVERITY_LEVEL) return false;
    if (*flag == BCLog::NONE) return true;
 
    STDLOCK(m_cs);
    m_category_log_levels[*flag] = level.value();
    return true;
}
 
bool util::log::ShouldDebugLog(Category category)
{
    return LogInstance().WillLogCategoryLevel(static_cast<BCLog::LogFlags>(category), util::log::Level::Debug);
}
 
bool util::log::ShouldTraceLog(Category category)
{
    return LogInstance().WillLogCategoryLevel(static_cast<BCLog::LogFlags>(category), util::log::Level::Trace);
}
 
void util::log::Log(util::log::Entry entry)
{
    BCLog::Logger& logger{LogInstance()};
    if (logger.Enabled()) {
        logger.LogPrint(std::move(entry));
    }
}