diff --git a/src/logging.cpp b/src/logging.cpp index 3a9d84f539c..3373063c05c 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -75,12 +75,17 @@ bool BCLog::Logger::StartLogging() // dump buffered messages from before we opened the log m_buffering = false; if (m_buffer_lines_discarded > 0) { - LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), SourceLocation{__func__}, BCLog::ALL, Level::Info, /*should_ratelimit=*/false); + 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{buflog.str}; - FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime); + std::string s{Format(buflog)}; m_msgs_before_open.pop_front(); if (m_print_to_file) FileWriteStr(s, m_fileout); @@ -366,11 +371,11 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l return s; } -static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog) +static size_t MemUsage(const util::log::Entry& log) { - return memusage::DynamicUsage(buflog.str) + - memusage::DynamicUsage(buflog.threadname) + - memusage::MallocUsage(sizeof(memusage::list_node)); + return memusage::DynamicUsage(log.message) + + memusage::DynamicUsage(log.thread_name) + + memusage::MallocUsage(sizeof(memusage::list_node)); } BCLog::LogRateLimiter::LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window) @@ -404,47 +409,38 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume( return status; } -void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, const SourceLocation& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const +std::string BCLog::Logger::Format(const util::log::Entry& entry) const { - if (!str.ends_with('\n')) str.push_back('\n'); - - str.insert(0, GetLogPrefix(category, level)); - - if (m_log_sourcelocations) { - str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name_short())); - } + std::string result{LogTimestampStr(entry.timestamp, entry.mocktime)}; if (m_log_threadnames) { - str.insert(0, strprintf("[%s] ", (threadname.empty() ? "unknown" : threadname))); + result += strprintf("[%s] ", (entry.thread_name.empty() ? "unknown" : entry.thread_name)); } - str.insert(0, LogTimestampStr(now, mocktime)); + 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(entry.category), entry.level); + result += LogEscapeMessage(entry.message); + + if (!result.ends_with('\n')) result += '\n'; + return result; } -void BCLog::Logger::LogPrintStr(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) +void BCLog::Logger::LogPrint(util::log::Entry entry) { STDLOCK(m_cs); - return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit); + return LogPrint_(std::move(entry)); } // NOLINTNEXTLINE(misc-no-recursion) -void BCLog::Logger::LogPrintStr_(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) +void BCLog::Logger::LogPrint_(util::log::Entry entry) { - std::string str_prefixed = LogEscapeMessage(str); - if (m_buffering) { { - BufferedLog buf{ - .now = SystemClock::now(), - .mocktime = GetMockTime(), - .str = str_prefixed, - .threadname = util::ThreadGetInternalName(), - .source_loc = std::move(source_loc), - .category = category, - .level = level, - }; - m_cur_buffer_memusage += MemUsage(buf); - m_msgs_before_open.push_back(std::move(buf)); + m_cur_buffer_memusage += MemUsage(entry); + m_msgs_before_open.push_back(std::move(entry)); } while (m_cur_buffer_memusage > m_max_buffer_memusage) { @@ -460,21 +456,26 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, SourceLocation&& source_l return; } - FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); + std::string str_prefixed{Format(entry)}; bool ratelimit{false}; - if (should_ratelimit && m_limiter) { - auto status{m_limiter->Consume(source_loc, str_prefixed)}; + 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) - LogPrintStr_(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.", - source_loc.file_name(), source_loc.line(), source_loc.function_name_short(), - m_limiter->m_max_bytes, - Ticks(m_limiter->m_reset_window)), - SourceLocation{__func__}, LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite 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(m_limiter->m_reset_window)), + }); } else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) { ratelimit = true; } @@ -612,6 +613,6 @@ void util::log::Log(util::log::Entry entry) { BCLog::Logger& logger{LogInstance()}; if (logger.Enabled()) { - logger.LogPrintStr(std::move(entry.message), std::move(entry.source_loc), static_cast(entry.category), entry.level, entry.should_ratelimit); + logger.LogPrint(std::move(entry)); } } diff --git a/src/logging.h b/src/logging.h index 3417b4b7fd2..67f5d6ef007 100644 --- a/src/logging.h +++ b/src/logging.h @@ -129,21 +129,11 @@ namespace BCLog { class Logger { - public: - struct BufferedLog { - SystemClock::time_point now; - std::chrono::seconds mocktime; - std::string str, threadname; - SourceLocation source_loc; - LogFlags category; - Level level; - }; - private: mutable StdMutex m_cs; // Can not use Mutex from sync.h because in debug mode it would cause a deadlock when a potential deadlock was detected FILE* m_fileout GUARDED_BY(m_cs) = nullptr; - std::list m_msgs_before_open GUARDED_BY(m_cs); + std::list m_msgs_before_open GUARDED_BY(m_cs); bool m_buffering GUARDED_BY(m_cs) = true; //!< Buffer messages before logging can be started. 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}; @@ -162,16 +152,15 @@ namespace BCLog { /** Log categories bitfield. */ std::atomic m_categories{BCLog::NONE}; - void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, const SourceLocation& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const; + std::string Format(const util::log::Entry& entry) const; std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const; /** Slots that connect to the print signal */ - std::list> m_print_callbacks GUARDED_BY(m_cs) {}; + std::list> m_print_callbacks GUARDED_BY(m_cs){}; - /** Send a string to the log output (internal) */ - void LogPrintStr_(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) - EXCLUSIVE_LOCKS_REQUIRED(m_cs); + /** Send an entry to the log output (internal) */ + void LogPrint_(util::log::Entry log_entry) EXCLUSIVE_LOCKS_REQUIRED(m_cs); std::string GetLogPrefix(LogFlags category, Level level) const; @@ -188,9 +177,8 @@ namespace BCLog { fs::path m_file_path; std::atomic m_reopen_file{false}; - /** Send a string to the log output */ - void LogPrintStr(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit) - EXCLUSIVE_LOCKS_REQUIRED(!m_cs); + /** Send an entry to the log output */ + void LogPrint(util::log::Entry log_entry) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ bool Enabled() const EXCLUSIVE_LOCKS_REQUIRED(!m_cs) diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index dfefd91769d..37a43e9740c 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -110,7 +110,7 @@ BOOST_AUTO_TEST_CASE(logging_timer) BOOST_CHECK_EQUAL(micro_timer.LogMsg("msg").substr(0, result_prefix.size()), result_prefix); } -BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) +BOOST_FIXTURE_TEST_CASE(logging_LogPrint, LogSetup) { LogInstance().m_log_sourcelocations = true; @@ -134,7 +134,7 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) std::vector expected; for (auto& [msg, category, level, prefix, loc] : cases) { expected.push_back(tfm::format("[%s:%s] [%s] %s%s", util::RemovePrefix(loc.file_name(), "./"), loc.line(), loc.function_name_short(), prefix, msg)); - LogInstance().LogPrintStr(msg, std::move(loc), category, level, /*should_ratelimit=*/false); + LogInstance().LogPrint({.category = category, .level = level, .should_ratelimit = false, .source_loc = std::move(loc), .message = msg}); } std::vector log_lines{ReadDebugLogLines()}; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); diff --git a/src/util/log.h b/src/util/log.h index 1bec49f2298..9394161f61d 100644 --- a/src/util/log.h +++ b/src/util/log.h @@ -10,6 +10,8 @@ #include // IWYU pragma: export #include #include +#include +#include #include #include @@ -23,8 +25,9 @@ public: /// The func argument must be constructed from the C++11 __func__ macro. /// Ref: https://en.cppreference.com/w/cpp/language/function.html#func /// Non-static string literals are not supported. - SourceLocation(const char* func, - std::source_location loc = std::source_location::current()) + explicit SourceLocation( + const char* func, + std::source_location loc = std::source_location::current()) : m_func{func}, m_loc{loc} {} std::string_view file_name() const { return m_loc.file_name(); } @@ -52,6 +55,9 @@ struct Entry { Category category; Level level; bool should_ratelimit{false}; //!< Hint for consumers if this entry should be ratelimited + SystemClock::time_point timestamp{SystemClock::now()}; + std::chrono::seconds mocktime{GetMockTime()}; + std::string thread_name{util::ThreadGetInternalName()}; SourceLocation source_loc; std::string message; };