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