cryptogera/bitcoin
1
0
Fork 0
mirror of https://github.com/bitcoin/bitcoin.git synced 2026-01-31 10:41:08 +00:00
Code Issues Packages Projects Releases Wiki Activity

Merge bitcoin/bitcoin#34088: log: Use __func__ for -logsourcelocations

Browse Source 
facd3d56ccbe2414a5f2b75be7132cd8b904f1e9 log: Use `__func__` for -logsourcelocations (MarcoFalke)

Pull request description:

  The `-logsourcelocations` option was recently changed to print the full function signature, as a side-effect of moving toward `std::source_location` internally.

  This is fine, but at least for me, it makes debugging functional test failures harder, because the log is just so massively verbose, with questionable benefit.

  I think the historically used file name, line number, and plain `__func__` name are more than sufficient for `-logsourcelocations`.

  So switch back to using that.

  For reference, a verbose log may look like:

  ```
  ...
  node0 2025-12-17T07:28:37.528146Z [init] [checkqueue.h:147] [CCheckQueue<T, R>::CCheckQueue(unsigned int, int) [with T = CScriptCheck; R = std::pair<ScriptError_t, std::__cxx11::basic_string<char> >]] Script verificatio
  n uses 1 additional threads
  ...
  ```

  I don't think there is value in printing stuff, like the (anon) namespace, the class template args, or the functionn (template) args. The following should be more than sufficient:

  ```
  ...
  node0 2025-12-17T09:45:57.017122Z [init] [checkqueue.h:147] [CCheckQueue] Script verification uses 1 additional threads
  ...

ACKs for top commit:
  ajtowns:
    ACK facd3d56ccbe2414a5f2b75be7132cd8b904f1e9 -- those long signatures are terrible
  stickies-v:
    ACK facd3d56ccbe2414a5f2b75be7132cd8b904f1e9

Tree-SHA512: 22fd1f0074fc6e85754967f9219659f57c905005a2bea9176f0b439abec324d7e6c2f875c8951934a3b11ef7e9d7e38d5d5d307e2bd1e000bc27ee85635cd668
This commit is contained in:
merge-script 2025-12-18 12:17:20 +00:00
commit 80b1b5917d
No known key found for this signature in database
GPG Key ID: 2EEB9F5CC09526C1
4 changed files with 53 additions and 29 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
doc/release-notes-34088.md Normal file
View File

@ -0,0 +1,2 @@
- When `-logsourcelocations` is enabled, the log output now contains just the
function name instead of the entire function signature. (#34088)

18
src/logging.cpp
View File

@ -75,7 +75,7 @@ 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), std::source_location::current(), BCLog::ALL, Level::Info, /*should_ratelimit=*/false);
LogPrintStr_(strprintf("Early logging buffer overflowed, %d log lines discarded.\n", m_buffer_lines_discarded), SourceLocation{__func__}, BCLog::ALL, Level::Info, /*should_ratelimit=*/false);
}
while (!m_msgs_before_open.empty()) {
const auto& buflog = m_msgs_before_open.front();
@ -388,7 +388,7 @@ std::shared_ptr<BCLog::LogRateLimiter> BCLog::LogRateLimiter::Create(
}
BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
const std::source_location& source_loc,
const SourceLocation& source_loc,
const std::string& str)
{
StdLockGuard scoped_lock(m_mutex);
@ -403,14 +403,14 @@ BCLog::LogRateLimiter::Status BCLog::LogRateLimiter::Consume(
return status;
}
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
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
{
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()));
str.insert(0, strprintf("[%s:%d] [%s] ", RemovePrefixView(source_loc.file_name(), "./"), source_loc.line(), source_loc.function_name_short()));
}
if (m_log_threadnames) {
@ -420,14 +420,14 @@ 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::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
void BCLog::Logger::LogPrintStr(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
{
StdLockGuard scoped_lock(m_cs);
return LogPrintStr_(str, std::move(source_loc), category, level, should_ratelimit);
}
// NOLINTNEXTLINE(misc-no-recursion)
void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
void BCLog::Logger::LogPrintStr_(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
{
std::string str_prefixed = LogEscapeMessage(str);
@ -470,10 +470,10 @@ void BCLog::Logger::LogPrintStr_(std::string_view str, std::source_location&& so
"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(),
source_loc.file_name(), source_loc.line(), source_loc.function_name_short(),
m_limiter->m_max_bytes,
Ticks<std::chrono::seconds>(m_limiter->m_reset_window)),
std::source_location::current(), LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion
SourceLocation{__func__}, LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false); // with should_ratelimit=false, this cannot lead to infinite recursion
} else if (status == LogRateLimiter::Status::STILL_SUPPRESSED) {
ratelimit = true;
}
@ -564,7 +564,7 @@ void BCLog::LogRateLimiter::Reset()
LogPrintLevel_(
LogFlags::ALL, Level::Warning, /*should_ratelimit=*/false,
"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(),
source_loc.file_name(), source_loc.line(), source_loc.function_name_short(),
stats.m_dropped_bytes, Ticks<std::chrono::seconds>(m_reset_window));
}
}

42
src/logging.h
View File

@ -37,15 +37,35 @@ extern const char * const DEFAULT_DEBUGLOGFILE;
extern bool fLogIPs;
/// Like std::source_location, but allowing to override the function name.
class SourceLocation
{
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())
: m_func{func}, m_loc{loc} {}
std::string_view file_name() const { return m_loc.file_name(); }
std::uint_least32_t line() const { return m_loc.line(); }
std::string_view function_name_short() const { return m_func; }
private:
std::string_view m_func;
std::source_location m_loc;
};
struct SourceLocationEqual {
bool operator()(const std::source_location& lhs, const std::source_location& rhs) const noexcept
bool operator()(const SourceLocation& lhs, const SourceLocation& 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
size_t operator()(const SourceLocation& s) const noexcept
{
// Use CSipHasher(0, 0) as a simple way to get uniform distribution.
return size_t(CSipHasher(0, 0)
@ -131,7 +151,7 @@ namespace BCLog {
mutable StdMutex m_mutex;
//! Stats for each source location that has attempted to log something.
std::unordered_map<std::source_location, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
std::unordered_map<SourceLocation, Stats, SourceLocationHasher, SourceLocationEqual> m_source_locations GUARDED_BY(m_mutex);
//! Whether any log locations are suppressed. Cached view on m_source_locations for performance reasons.
std::atomic<bool> m_suppression_active{false};
LogRateLimiter(uint64_t max_bytes, std::chrono::seconds reset_window);
@ -163,7 +183,7 @@ namespace BCLog {
//! Consumes `source_loc`'s available bytes corresponding to the size of the (formatted)
//! `str` and returns its status.
[[nodiscard]] Status Consume(
const std::source_location& source_loc,
const SourceLocation& source_loc,
const std::string& str) EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
//! Resets all usage to zero. Called periodically by the scheduler.
void Reset() EXCLUSIVE_LOCKS_REQUIRED(!m_mutex);
@ -178,7 +198,7 @@ namespace BCLog {
SystemClock::time_point now;
std::chrono::seconds mocktime;
std::string str, threadname;
std::source_location source_loc;
SourceLocation source_loc;
LogFlags category;
Level level;
};
@ -206,7 +226,7 @@ namespace BCLog {
/** Log categories bitfield. */
std::atomic<CategoryMask> m_categories{BCLog::NONE};
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;
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 LogTimestampStr(SystemClock::time_point now, std::chrono::seconds mocktime) const;
@ -214,7 +234,7 @@ namespace BCLog {
std::list<std::function<void(const std::string&)>> m_print_callbacks GUARDED_BY(m_cs) {};
/** Send a string to the log output (internal) */
void LogPrintStr_(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
void LogPrintStr_(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
EXCLUSIVE_LOCKS_REQUIRED(m_cs);
std::string GetLogPrefix(LogFlags category, Level level) const;
@ -233,7 +253,7 @@ namespace BCLog {
std::atomic<bool> m_reopen_file{false};
/** Send a string to the log output */
void LogPrintStr(std::string_view str, std::source_location&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
void LogPrintStr(std::string_view str, SourceLocation&& source_loc, BCLog::LogFlags category, BCLog::Level level, bool should_ratelimit)
EXCLUSIVE_LOCKS_REQUIRED(!m_cs);
/** Returns whether logs will be written to any output */
@ -347,7 +367,7 @@ static inline bool LogAcceptCategory(BCLog::LogFlags category, BCLog::Level leve
bool GetLogCategory(BCLog::LogFlags& flag, std::string_view str);
template <typename... Args>
inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
inline void LogPrintFormatInternal(SourceLocation&& source_loc, BCLog::LogFlags flag, BCLog::Level level, bool should_ratelimit, util::ConstevalFormatString<sizeof...(Args)> fmt, const Args&... args)
{
if (LogInstance().Enabled()) {
std::string log_msg;
@ -360,7 +380,9 @@ inline void LogPrintFormatInternal(std::source_location&& source_loc, BCLog::Log
}
}
#define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(std::source_location::current(), category, level, should_ratelimit, __VA_ARGS__)
// Allow __func__ to be used in any context without warnings:
// NOLINTNEXTLINE(bugprone-lambda-function-name)
#define LogPrintLevel_(category, level, should_ratelimit, ...) LogPrintFormatInternal(SourceLocation{__func__}, category, level, should_ratelimit, __VA_ARGS__)
// Log unconditionally. Uses basic rate limiting to mitigate disk filling attacks.
// Be conservative when using functions that unconditionally log to debug.log!

20
src/test/logging_tests.cpp
View File

@ -118,21 +118,21 @@ BOOST_FIXTURE_TEST_CASE(logging_LogPrintStr, LogSetup)
BCLog::LogFlags category;
BCLog::Level level;
std::string prefix;
std::source_location loc;
SourceLocation 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()},
{"foo1: bar1", BCLog::NET, BCLog::Level::Debug, "[net] ", SourceLocation{__func__}},
{"foo2: bar2", BCLog::NET, BCLog::Level::Info, "[net:info] ", SourceLocation{__func__}},
{"foo3: bar3", BCLog::ALL, BCLog::Level::Debug, "[debug] ", SourceLocation{__func__}},
{"foo4: bar4", BCLog::ALL, BCLog::Level::Info, "", SourceLocation{__func__}},
{"foo5: bar5", BCLog::NONE, BCLog::Level::Debug, "[debug] ", SourceLocation{__func__}},
{"foo6: bar6", BCLog::NONE, BCLog::Level::Info, "", SourceLocation{__func__}},
};
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));
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);
}
std::vector<std::string> log_lines{ReadDebugLogLines()};
@ -306,8 +306,8 @@ BOOST_AUTO_TEST_CASE(logging_log_rate_limiter)
auto& limiter{*Assert(limiter_)};
using Status = BCLog::LogRateLimiter::Status;
auto source_loc_1{std::source_location::current()};
auto source_loc_2{std::source_location::current()};
auto source_loc_1{SourceLocation{__func__}};
auto source_loc_2{SourceLocation{__func__}};
// A fresh limiter should not have any suppressions
BOOST_CHECK(!limiter.SuppressionsActive());