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.

3 files changed, 114 insertions, 17 deletions

diff --git a/src/rpc.cpp b/src/rpc.cpp
index a4b53ca..2e8f4b8 100644
--- a/src/rpc.cpp
+++ b/src/rpc.cpp
@@ -1732,7 +1732,9 @@ static void FlushMaturePayouts()
             }
             int64 total = 0;
             for (auto& kv : it->amounts) total += kv.second;
-            LogPrint("payout", "[payout] block %d (%s) was orphaned -- voiding %zu"
+            // Always: one line per voided entry, never a collapsed summary.
+            // A reorg voids these in a burst from this one source line.
+            LogPrintAlways("payout", "[payout] block %d (%s) was orphaned -- voiding %zu"
                      " payment(s) totalling %s\n",
                      it->blockHeight, it->blockHash.ToString().substr(0, 14).c_str(),
                      it->amounts.size(), FormatMoney(total).c_str());
@@ -2036,7 +2038,7 @@ static void PayoutThreadFn(void*)
             // funding block can land at any point in that window. Upstream has
             // no equivalent -- it decides once, when the entry matures.
             if (!PayoutBlockStillOnChain(r.blockHash)) {
-                LogPrint("payout", "[payout] block %d (%s) orphaned while queued"
+                LogPrintAlways("payout", "[payout] block %d (%s) orphaned while queued"
                          " -- dropping %s to %s\n",
                          r.blockHeight, r.blockHash.ToString().substr(0, 14).c_str(),
                          FormatMoney(r.amount).c_str(), r.address.c_str());
@@ -2205,7 +2207,7 @@ static void PayoutThreadFn(void*)
                 // described by at least one of them at every instant.
                 RecordPayoutTxid(r, wtx.GetHash().GetHex());
                 ForgetPayment(r);
-                LogPrint("payout", "[payout] paid %s to %s (tx %s)\n",
+                LogPrintAlways("payout", "[payout] paid %s to %s (tx %s)\n",
                          FormatMoney(r.amount).c_str(), r.address.c_str(),
                          wtx.GetHash().ToString().substr(0, 12).c_str());
             } else {
@@ -2263,7 +2265,7 @@ static void PayoutThreadFn(void*)
                     // going away must not turn the log into one line a minute
                     // forever, and must not go quiet either.
                     if (r.retries <= 5 || r.retries % 60 == 0)
-                        LogPrint("payout", "[payout] FAILED to pay %s to %s"
+                        LogPrintAlways("payout", "[payout] FAILED to pay %s to %s"
                                  " (%s spendable, wallet unlocked, block %d on"
                                  " the main chain) -- attempt %d, retrying in"
                                  " 60s; this debt stands until it is paid\n",
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<std::string, LogDedupState> 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<LogDedupFlush>& out)
+{
+    for (std::map<std::string, LogDedupState>::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<LogDedupFlush> 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<std::string, LogDedupState>::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());
+}
+
 
 
 
diff --git a/src/util.h b/src/util.h
index d72518b..fe605a1 100644
--- a/src/util.h
+++ b/src/util.h
@@ -106,15 +106,29 @@ extern bool fDebug;
 //   2. Burst collapse: repeated LogPrint() calls from the *same source line*
 //      only emit one line per DEDUP_WINDOW_SECS; if more calls land inside
 //      that window they're counted instead of reprinted, and the count is
-//      flushed as a single "(xN similar in Ws)" line the moment the window
-//      rolls over. A loop discovering 500 peers by address now produces a
-//      small, bounded number of lines instead of 500 -- log growth is capped
-//      by elapsed time, not by how many similar events happen to fire.
+//      flushed as a single "(xN similar in Ws)" line once the window expires
+//      -- whether or not that call site ever fires again. A loop discovering
+//      500 peers by address now produces a small, bounded number of lines
+//      instead of 500 -- log growth is capped by elapsed time, not by how
+//      many similar events happen to fire.
+//
+// Use LogPrintAlways() instead for anything that reports an irreversible
+// change to money: an obligation voided, a payment sent, a payment that
+// failed. One line standing in for an unknown number of identical events is
+// a tidy report of peer chatter and a false report of a ledger. A reorg
+// voiding 100 entries hits one source line 100 times inside one window;
+// under LogPrint() that read as a single block losing a single 49.49 BTF
+// payment, while 4,950 BTF of obligations were actually destroyed, and the
+// discrepancy was only found by counting entries in pending_payouts.json
+// (issue #3). Bounded log growth is not worth that ambiguity here.
 // ---------------------------------------------------------------------------
 bool LogAcceptsCategory(const char* category);
 void LogPrintDedup(const char* category, const char* file, int line, const std::string& msg);
+void LogPrintNoCollapse(const char* category, const std::string& msg);
 #define LogPrint(category, ...) \
     do { if (LogAcceptsCategory(category)) LogPrintDedup((category), __FILE__, __LINE__, strprintf(__VA_ARGS__)); } while (0)
+#define LogPrintAlways(category, ...) \
+    do { if (LogAcceptsCategory(category)) LogPrintNoCollapse((category), strprintf(__VA_ARGS__)); } while (0)
 
 // Every format string in this project goes through one of the four functions
 // below -- `printf` itself is remapped to OutputDebugStringF just above, and