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