diff --git a/src/logging.cpp b/src/logging.cpp index eca6eac6727..65cd993d7d0 100644 --- a/src/logging.cpp +++ b/src/logging.cpp @@ -12,8 +12,10 @@ #include #include +#include #include #include +#include using util::Join; using util::RemovePrefixView; @@ -73,12 +75,12 @@ 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), __func__, __FILE__, __LINE__, BCLog::ALL, Level::Info); + LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), std::source_location::current(), BCLog::ALL, Level::Info); } 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_file, buflog.source_line, buflog.logging_function, buflog.threadname, buflog.now, buflog.mocktime); + FormatLogStrInPlace(s, buflog.category, buflog.level, buflog.source_loc, buflog.threadname, buflog.now, buflog.mocktime); m_msgs_before_open.pop_front(); if (m_print_to_file) FileWriteStr(s, m_fileout); @@ -364,7 +366,9 @@ std::string BCLog::Logger::GetLogPrefix(BCLog::LogFlags category, BCLog::Level l static size_t MemUsage(const BCLog::Logger::BufferedLog& buflog) { - return buflog.str.size() + buflog.logging_function.size() + buflog.source_file.size() + buflog.threadname.size() + memusage::MallocUsage(sizeof(memusage::list_node)); + return memusage::DynamicUsage(buflog.str) + + memusage::DynamicUsage(buflog.threadname) + + memusage::MallocUsage(sizeof(memusage::list_node)); } BCLog::LogRateLimiter::LogRateLimiter( @@ -391,14 +395,14 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume( return status; } -void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const +void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags category, BCLog::Level level, const std::source_location& source_loc, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) 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_file, "./"), source_line, logging_function)); + str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name())); } if (m_log_threadnames) { @@ -408,28 +412,26 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego str.insert(0, LogTimestampStr(now, mocktime)); } -void BCLog::Logger::LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) +void BCLog::Logger::LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) { StdLockGuard scoped_lock(m_cs); - return LogPrintStr_(str, logging_function, source_file, source_line, category, level); + return LogPrintStr_(str, std::move(source_loc), category, level); } -void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) +void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) { std::string str_prefixed = LogEscapeMessage(str); if (m_buffering) { { BufferedLog buf{ - .now=SystemClock::now(), - .mocktime=GetMockTime(), - .str=str_prefixed, - .logging_function=std::string(logging_function), - .source_file=std::string(source_file), - .threadname=util::ThreadGetInternalName(), - .source_line=source_line, - .category=category, - .level=level, + .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)); @@ -448,7 +450,7 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::string_view logging_ return; } - FormatLogStrInPlace(str_prefixed, category, level, source_file, source_line, logging_function, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); + FormatLogStrInPlace(str_prefixed, category, level, source_loc, util::ThreadGetInternalName(), SystemClock::now(), GetMockTime()); if (m_print_to_console) { // print to console diff --git a/src/logging.h b/src/logging.h index 7411d33f5f0..6ad6739adf8 100644 --- a/src/logging.h +++ b/src/logging.h @@ -184,8 +184,8 @@ namespace BCLog { struct BufferedLog { SystemClock::time_point now; std::chrono::seconds mocktime; - std::string str, logging_function, source_file, threadname; - int source_line; + std::string str, threadname; + std::source_location source_loc; LogFlags category; Level level; }; @@ -210,7 +210,7 @@ namespace BCLog { /** Log categories bitfield. */ std::atomic m_categories{BCLog::NONE}; - void FormatLogStrInPlace(std::string& str, LogFlags category, Level level, std::string_view source_file, int source_line, std::string_view logging_function, std::string_view threadname, SystemClock::time_point now, std::chrono::seconds mocktime) const; + 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; @@ -218,7 +218,7 @@ namespace BCLog { std::list> m_print_callbacks GUARDED_BY(m_cs) {}; /** Send a string to the log output (internal) */ - void LogPrintStr_(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) EXCLUSIVE_LOCKS_REQUIRED(m_cs); std::string GetLogPrefix(LogFlags category, Level level) const; @@ -237,7 +237,7 @@ namespace BCLog { std::atomic m_reopen_file{false}; /** Send a string to the log output */ - void LogPrintStr(std::string_view str, std::string_view logging_function, std::string_view source_file, int source_line, BCLog::LogFlags category, BCLog::Level level) + void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level) EXCLUSIVE_LOCKS_REQUIRED(!m_cs); /** Returns whether logs will be written to any output */ @@ -334,7 +334,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str); template -inline void LogPrintFormatInternal(std::string_view logging_function, std::string_view source_file, const int source_line, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) +inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString fmt, const Args&... args) { if (LogInstance().Enabled()) { std::string log_msg; @@ -343,11 +343,11 @@ inline void LogPrintFormatInternal(std::string_view logging_function, std::strin } catch (tinyformat::format_error& fmterr) { log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt; } - LogInstance().LogPrintStr(log_msg, logging_function, source_file, source_line, flag, level); + LogInstance().LogPrintStr(log_msg, std::move(source_loc), flag, level); } } -#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(__func__, __FILE__, __LINE__, category, level, __VA_ARGS__) +#define LogPrintLevel_(category, level, ...) LogPrintFormatInternal(std::source_location::current(), category, level, __VA_ARGS__) // Log unconditionally. // Be conservative when using functions that unconditionally log to debug.log! diff --git a/src/test/logging_tests.cpp b/src/test/logging_tests.cpp index 5d24ad771c2..8cf0735b086 100644 --- a/src/test/logging_tests.cpp +++ b/src/test/logging_tests.cpp @@ -7,12 +7,16 @@ #include #include #include +#include +#include +#include #include #include #include #include #include +#include #include #include #include @@ -88,25 +92,34 @@ BOOST_AUTO_TEST_CASE(logging_timer) BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) { LogInstance().m_log_sourcelocations = true; - LogInstance().LogPrintStr("foo1: bar1", "fn1", "src1", 1, BCLog::LogFlags::NET, BCLog::Level::Debug); - LogInstance().LogPrintStr("foo2: bar2", "fn2", "src2", 2, BCLog::LogFlags::NET, BCLog::Level::Info); - LogInstance().LogPrintStr("foo3: bar3", "fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug); - LogInstance().LogPrintStr("foo4: bar4", "fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info); - LogInstance().LogPrintStr("foo5: bar5", "fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug); - LogInstance().LogPrintStr("foo6: bar6", "fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info); + + struct Case { + std::string msg; + BCLog::LogFlags category; + BCLog::Level level; + std::string prefix; + std::source_location loc; + }; + + std::vector cases = { + {"foo1: bar1", BCLog::NET, BCLog::Level::Debug, "[net] ", std::source_location::current()}, + {"foo2: bar2", BCLog::NET, BCLog::Level::Info, "[net:info] ", std::source_location::current()}, + {"foo3: bar3", BCLog::ALL, BCLog::Level::Debug, "[debug] ", std::source_location::current()}, + {"foo4: bar4", BCLog::ALL, BCLog::Level::Info, "", std::source_location::current()}, + {"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ", std::source_location::current()}, + {"foo6: bar6", BCLog::NONE, BCLog::Level::Info, "", std::source_location::current()}, + }; + + 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(), prefix, msg)); + LogInstance().LogPrintStr(msg, std::move(loc), category, level); + } std::ifstream file{tmp_log_path}; std::vector log_lines; for (std::string log; std::getline(file, log);) { log_lines.push_back(log); } - std::vector expected = { - "[src1:1] [fn1] [net] foo1: bar1", - "[src2:2] [fn2] [net:info] foo2: bar2", - "[src3:3] [fn3] [debug] foo3: bar3", - "[src4:4] [fn4] foo4: bar4", - "[src5:5] [fn5] [debug] foo5: bar5", - "[src6:6] [fn6] foo6: bar6", - }; BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end()); } diff --git a/test/functional/feature_config_args.py b/test/functional/feature_config_args.py index c5e3c33b14d..12a82ced9c3 100755 --- a/test/functional/feature_config_args.py +++ b/test/functional/feature_config_args.py @@ -84,7 +84,7 @@ class ConfArgsTest(BitcoinTestFramework): self.log.debug('Verifying that disabling of the config file means garbage inside of it does ' \ 'not prevent the node from starting, and message about existing config file is logged') - ignored_file_message = [f'[InitConfig] Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.'] + ignored_file_message = [f'Data directory "{self.nodes[0].datadir_path}" contains a "bitcoin.conf" file which is explicitly ignored using -noconf.'] with self.nodes[0].assert_debug_log(timeout=60, expected_msgs=ignored_file_message): self.start_node(0, extra_args=settings + ['-noconf']) self.stop_node(0)