From 03a69ccfb36861948e11b0871bb9af8f0b280709 Mon Sep 17 00:00:00 2001 From: bitflash-maintainer Date: Wed, 2 Sep 2026 14:14:52 +0000 Subject: payout: never collapse a log line that reports money moving LogPrint()'s burst collapse is right for share and peer chatter and wrong for anything that reports an irreversible change to money. A reorg voided 100 ledger entries totalling 4,950 BTF and the log carried one line, naming one block and 49.49 BTF. The other 99 were counted and never printed, and no "(N similar)" summary appeared either -- a summary was only ever flushed when that same call site fired again, and after the reorg it never did. The missing 4,950 BTF was found by counting entries in pending_payouts.json. Add LogPrintAlways(), which skips the collapse entirely, and move the four payout lines that report money to it: an obligation voided, an obligation dropped, a payment sent, a payment that failed. All four are bursty by nature -- one reorg voids every entry funded by the orphaned block, from a single source line -- which is precisely why one line must not stand in for all of them. Their volume is bounded by how much money moved, which is a number worth the lines. Also sweep expired windows for every call site rather than only the one currently logging, so a burst that stops is still summarised, and report the window's real elapsed time instead of a hardcoded 3s. --- src/util.cpp | 99 ++++++++++++++++++++++++++++++++++++++++++++++++++++++------ 1 file changed, 90 insertions(+), 9 deletions(-) (limited to 'src/util.cpp') diff --git a/src/util.cpp b/src/util.cpp index 0cd0133..b5b145f 100644 --- a/src/util.cpp +++ b/src/util.cpp @@ -47,6 +47,61 @@ struct LogDedupState { static std::map g_logDedup; static CCriticalSection cs_logDedup; +// A pending "(N similar)" summary, lifted out of the table while the lock is +// held and written after it is released. +struct LogDedupFlush { + std::string category; + int suppressed; + int64 elapsed; // how long the window that counted them ran + std::string lastMsg; +}; + +static int64 g_logDedupLastSweep = 0; + +static void EmitDedupSummary(const LogDedupFlush& f) +{ + OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", + f.category.c_str(), f.suppressed, + (long long)f.elapsed, f.lastMsg.c_str()); +} + +// A window is otherwise only closed out when its own call site fires again, so +// a burst that simply stops -- 100 ledger entries voided in one pass and then +// silence -- leaves its count sitting in the table and the summary is never +// written at all. That is how 99 of 100 voids went unreported, with no "(N +// similar)" line to say anything was missing (issue #3). Sweep every expired +// window instead, so a finished burst is summarised as soon as anything at all +// is logged. +// +// Expired entries are erased rather than reopened: the window is over, so there +// is no state left worth keeping, and the next call from that site then takes +// the "first time" path and prints directly -- exactly what the rollover branch +// below would have done. It also stops the table growing without bound. +// +// Caller holds cs_logDedup; the summaries are written after it is released. +static void SweepExpiredWindowsLocked(int64 now, std::vector& out) +{ + for (std::map::iterator it = g_logDedup.begin(); + it != g_logDedup.end(); ) + { + if (now - it->second.windowStart < DEDUP_WINDOW_SECS) + { + ++it; + continue; + } + if (it->second.suppressed > 0) + { + LogDedupFlush f; + f.category = it->first.substr(0, it->first.find('|')); + f.suppressed = it->second.suppressed; + f.elapsed = now - it->second.windowStart; + f.lastMsg = it->second.lastMsg; + out.push_back(f); + } + g_logDedup.erase(it++); + } +} + void LogPrintDedup(const char* category, const char* file, int line, const std::string& msgIn) { // Call sites follow the existing printf() convention of ending their @@ -61,11 +116,19 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: int64 now = GetTime(); bool fEmitNow = false; - int suppressedToFlush = 0; - std::string flushedMsg; + std::vector flushes; CRITICAL_BLOCK(cs_logDedup) { + // At most once a second. The table holds one entry per call site that + // has fired in the last few seconds, so the walk is short, but it must + // not run once per line of a burst. + if (now != g_logDedupLastSweep) + { + g_logDedupLastSweep = now; + SweepExpiredWindowsLocked(now, flushes); + } + std::map::iterator it = g_logDedup.find(key); if (it == g_logDedup.end()) { @@ -76,10 +139,18 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: } else if (now - it->second.windowStart >= DEDUP_WINDOW_SECS) { - // Window rolled over: flush what was suppressed during it (if - // anything), then start a new window with this call printed. - suppressedToFlush = it->second.suppressed; - flushedMsg = it->second.lastMsg; + // Window rolled over within the same second as the last sweep: + // flush what was suppressed during it (if anything), then start a + // new window with this call printed. + if (it->second.suppressed > 0) + { + LogDedupFlush f; + f.category = category; + f.suppressed = it->second.suppressed; + f.elapsed = now - it->second.windowStart; + f.lastMsg = it->second.lastMsg; + flushes.push_back(f); + } it->second.windowStart = now; it->second.suppressed = 0; it->second.lastMsg = msg; @@ -94,13 +165,23 @@ void LogPrintDedup(const char* category, const char* file, int line, const std:: } } - if (suppressedToFlush > 0) - OutputDebugStringF("[%s] (%d similar in %llds, last: %s)\n", - category, suppressedToFlush, (long long)DEDUP_WINDOW_SECS, flushedMsg.c_str()); + for (size_t i = 0; i < flushes.size(); i++) + EmitDedupSummary(flushes[i]); if (fEmitNow) OutputDebugStringF("[%s] %s\n", category, msg.c_str()); } +// LogPrintAlways() -- see the doc comment in util.h. No window, no counting, +// no table entry: every call writes its own line. +void LogPrintNoCollapse(const char* category, const std::string& msgIn) +{ + std::string msg = msgIn; + while (!msg.empty() && (msg.back() == '\n' || msg.back() == '\r')) + msg.pop_back(); + + OutputDebugStringF("[%s] %s\n", category, msg.c_str()); +} + -- cgit v1.2.3