highperfocused/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2025-08-28 20:12:19 +02:00
Code Issues Packages Projects Releases Wiki Activity

log: use std::source_location in place of __func__, __FILE__, __LINE__

Browse Source 
The std::source_location conveniently stores the file name, line number,
and function name of a source code location. We switch to using it instead
of the __func__ identifier and the __FILE__ and __LINE__ macros.

BufferedLog is changed to have a std::source_location member, replacing the
source_file, source_line, and logging_function members. As a result,
MemUsage no longer explicitly counts source_file or logging_function as the
std::source_location memory usage is included in the MallocUsage call.

This also changes the behavior of -logsourcelocations as std::source_location
includes the entire function signature. Because of this, the functional test
feature_config_args.py must be changed to no longer include the function
signature as the function signature can differ across platforms.

Co-Authored-By: Niklas Gogge <n.goeggi@gmail.com>
Co-Authored-By: stickies-v <stickies-v@protonmail.com>

Github-Pull: #32604
Rebased-From: a6a35cc0c2
This commit is contained in:
Eugene Siegel
2025-06-05 13:37:27 -04:00
committed by fanquake
parent 41262cc4d5
commit a0992a842e
4 changed files with 56 additions and 41 deletions
Download Patch File Download Diff File Expand all files Collapse all files

38
src/logging.cpp
View File

@@ -12,8 +12,10 @@
#include <util/time.h> #include <util/time.h>
#include <array> #include <array>
#include <cstring>
#include <map> #include <map>
#include <optional> #include <optional>
#include <utility>
using util::Join; using util::Join;
using util::RemovePrefixView; using util::RemovePrefixView;
@@ -73,12 +75,12 @@ bool BCLog::Logger::StartLogging()
// dump buffered messages from before we opened the log // dump buffered messages from before we opened the log
m_buffering = false; m_buffering = false;
if (m_buffer_lines_discarded > 0) { 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()) { while (!m_msgs_before_open.empty()) {
const auto& buflog = m_msgs_before_open.front(); const auto& buflog = m_msgs_before_open.front();
std::string s{buflog.str}; 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(); m_msgs_before_open.pop_front();
if (m_print_to_file) FileWriteStr(s, m_fileout); 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) 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<BCLog::Logger::BufferedLog>)); return memusage::DynamicUsage(buflog.str) +
memusage::DynamicUsage(buflog.threadname) +
memusage::MallocUsage(sizeof(memusage::list_node<BCLog::Logger::BufferedLog>));
} }
BCLog::LogRateLimiter::LogRateLimiter( BCLog::LogRateLimiter::LogRateLimiter(
@@ -391,14 +395,14 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
return status; 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'); if (!str.ends_with('\n')) str.push_back('\n');
str.insert(0, GetLogPrefix(category, level)); str.insert(0, GetLogPrefix(category, level));
if (m_log_sourcelocations) { 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) { if (m_log_threadnames) {
@@ -408,28 +412,26 @@ void BCLog::Logger::FormatLogStrInPlace(std::string& str, BCLog::LogFlags catego
str.insert(0, LogTimestampStr(now, mocktime)); 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); 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); std::string str_prefixed = LogEscapeMessage(str);
if (m_buffering) { if (m_buffering) {
{ {
BufferedLog buf{ BufferedLog buf{
.now=SystemClock::now(), .now = SystemClock::now(),
.mocktime=GetMockTime(), .mocktime = GetMockTime(),
.str=str_prefixed, .str = str_prefixed,
.logging_function=std::string(logging_function), .threadname = util::ThreadGetInternalName(),
.source_file=std::string(source_file), .source_loc = std::move(source_loc),
.threadname=util::ThreadGetInternalName(), .category = category,
.source_line=source_line, .level = level,
.category=category,
.level=level,
}; };
m_cur_buffer_memusage += MemUsage(buf); m_cur_buffer_memusage += MemUsage(buf);
m_msgs_before_open.push_back(std::move(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; 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) { if (m_print_to_console) {
// print to console // print to console

16
src/logging.h
View File

@@ -184,8 +184,8 @@ namespace BCLog {
struct BufferedLog { struct BufferedLog {
SystemClock::time_point now; SystemClock::time_point now;
std::chrono::seconds mocktime; std::chrono::seconds mocktime;
std::string str, logging_function, source_file, threadname; std::string str, threadname;
int source_line; std::source_location source_loc;
LogFlags category; LogFlags category;
Level level; Level level;
}; };
@@ -210,7 +210,7 @@ namespace BCLog {
/** Log categories bitfield. */ /** Log categories bitfield. */
std::atomic<CategoryMask> m_categories{BCLog::NONE}; std::atomic<CategoryMask> 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; std::string LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const;
@@ -218,7 +218,7 @@ namespace BCLog {
std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {}; std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {};
/** Send a string to the log output (internal) */ /** 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); EXCLUSIVE_LOCKS_REQUIRED(m_cs);
std::string GetLogPrefix(LogFlags category, Level level) const; std::string GetLogPrefix(LogFlags category, Level level) const;
@@ -237,7 +237,7 @@ namespace BCLog {
std::atomic<bool> m_reopen_file{false}; std::atomic<bool> m_reopen_file{false};
/** Send a string to the log output */ /** 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); EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
/** Returns whether logs will be written to any output */ /** 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); bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str);
template <typename... Args> template <typename... Args>
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<sizeof...(Args)> fmt, const Args&... args) inline void LogPrintFormatInternal(std::source_location&& source_loc, const BCLog::LogFlags flag, const BCLog::Level level, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
{ {
if (LogInstance().Enabled()) { if (LogInstance().Enabled()) {
std::string log_msg; std::string log_msg;
@@ -343,11 +343,11 @@ inline void LogPrintFormatInternal(std::string_view logging_function, std::strin
} catch (tinyformat::format_error& fmterr) { } catch (tinyformat::format_error& fmterr) {
log_msg = "Error \"" + std::string{fmterr.what()} + "\" while formatting log message: " + fmt.fmt; 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. // Log unconditionally.
// Be conservative when using functions that unconditionally log to debug.log! // Be conservative when using functions that unconditionally log to debug.log!

41
src/test/logging_tests.cpp
View File

@@ -7,12 +7,16 @@
#include <logging/timer.h> #include <logging/timer.h>
#include <scheduler.h> #include <scheduler.h>
#include <test/util/setup_common.h> #include <test/util/setup_common.h>
#include <tinyformat.h>
#include <util/fs.h>
#include <util/fs_helpers.h>
#include <util/string.h> #include <util/string.h>
#include <chrono> #include <chrono>
#include <fstream> #include <fstream>
#include <future> #include <future>
#include <iostream> #include <iostream>
#include <source_location>
#include <unordered_map> #include <unordered_map>
#include <utility> #include <utility>
#include <vector> #include <vector>
@@ -88,25 +92,34 @@ BOOST_AUTO_TEST_CASE(logging_timer)
BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup) BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
{ {
LogInstance().m_log_sourcelocations = true; 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); struct Case {
LogInstance().LogPrintStr("foo3: bar3", "fn3", "src3", 3, BCLog::LogFlags::ALL, BCLog::Level::Debug); std::string msg;
LogInstance().LogPrintStr("foo4: bar4", "fn4", "src4", 4, BCLog::LogFlags::ALL, BCLog::Level::Info); BCLog::LogFlags category;
LogInstance().LogPrintStr("foo5: bar5", "fn5", "src5", 5, BCLog::LogFlags::NONE, BCLog::Level::Debug); BCLog::Level level;
LogInstance().LogPrintStr("foo6: bar6", "fn6", "src6", 6, BCLog::LogFlags::NONE, BCLog::Level::Info); std::string prefix;
std::source_location loc;
};
std::vector<Case> 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<std::string> 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::ifstream file{tmp_log_path};
std::vector<std::string> log_lines; std::vector<std::string> log_lines;
for (std::string log; std::getline(file, log);) { for (std::string log; std::getline(file, log);) {
log_lines.push_back(log); log_lines.push_back(log);
} }
std::vector<std::string> 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()); BOOST_CHECK_EQUAL_COLLECTIONS(log_lines.begin(), log_lines.end(), expected.begin(), expected.end());
} }

2
test/functional/feature_config_args.py
View File

@@ -84,7 +84,7 @@ class ConfArgsTest(BitcoinTestFramework):
self.log.debug('Verifying that disabling of the config file means garbage inside of it does ' \ 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') '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): with self.nodes[0].assert_debug_log(timeout=60, expected_msgs=ignored_file_message):
self.start_node(0, extra_args=settings + ['-noconf']) self.start_node(0, extra_args=settings + ['-noconf'])
self.stop_node(0) self.stop_node(0)