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.

1 files changed, 90 insertions, 9 deletions

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());
+}
+