log: Adjust masternode staking output to fix issue #648 (#1006)

* Correct loglevel for ThreadStaker (#648) * No debug level for MakeStake kernel found (#648) * Time throttled logging for staker (#648) * Reverse logic in log time throttle filter * Simplify throttled logging * Minor refactors Co-authored-by: Prasanna Loganathar <[email protected]> Co-authored-by: Jouzo <[email protected]>
DeFiCh · Mar 18, 2022 · 54557c2 · 54557c2
1 parent 8aee91e
commit 54557c2
Show file tree

Hide file tree

Showing 3 changed files with 38 additions and 4 deletions.
diff --git a/src/logging.h b/src/logging.h
@@ -8,13 +8,15 @@
 
 #include <fs.h>
 #include <tinyformat.h>
+#include <util/time.h>
 
 #include <atomic>
 #include <cstdint>
 #include <list>
 #include <mutex>
 #include <string>
 #include <vector>
+#include <unordered_map>
 
 static const bool DEFAULT_LOGTIMEMICROS = false;
 static const bool DEFAULT_LOGIPS        = false;
@@ -168,4 +170,35 @@ static inline void LogPrint(const BCLog::LogFlags& category, const Args&... args
     }
 }
 
+/** Implementation that logs at most every x milliseconds. If the category is enabled, it does not time throttle */
+template <typename... Args>
+static inline void LogPrintCategoryOrThreadThrottled(const BCLog::LogFlags& category, std::string message_key, uint64_t milliseconds, const Args&... args)
+{
+    // Map containing pairs of message key and timestamp of last log
+    // In case different threads use the same message key, use thread_local
+    thread_local std::unordered_map<std::string, uint64_t> last_log_timestamps;
+
+    // Log directly if category is enabled..
+    if (LogAcceptCategory((category))) {
+        LogPrintf(args...);
+    } else { // .. and otherwise time throttle logging
+
+        int64_t current_time = GetTimeMillis();
+        auto it = last_log_timestamps.find(message_key);
+
+        if (it != last_log_timestamps.end()) {
+            if ((current_time - it->second) > milliseconds)
+            {
+                LogPrintf(args...);
+                it->second = current_time;
+            }
+        }        
+        else {
+            // No entry yet -> log directly and save timestamp
+            last_log_timestamps.insert(std::make_pair(message_key, current_time));
+            LogPrintf(args...);
+        }
+    }
+}
+
 #endif // DEFI_LOGGING_H
diff --git a/src/miner.cpp b/src/miner.cpp
@@ -9,14 +9,15 @@
 #include <chain.h>
 #include <chainparams.h>
 #include <coins.h>
-#include <consensus/tx_check.h>
 #include <consensus/consensus.h>
 #include <consensus/merkle.h>
+#include <consensus/tx_check.h>
 #include <consensus/tx_verify.h>
 #include <consensus/validation.h>
 #include <masternodes/anchors.h>
 #include <masternodes/masternodes.h>
 #include <masternodes/mn_checks.h>
+#include <memory.h>
 #include <net.h>
 #include <policy/feerate.h>
 #include <policy/policy.h>
@@ -960,10 +961,10 @@ void ThreadStaker::operator()(std::vector<ThreadStaker::Args> args, CChainParams
                     nMinted[arg.operatorID]++;
                 }
                 else if (status == Staker::Status::initWaiting) {
-                    LogPrintf("ThreadStaker: (%s) waiting init...\n", operatorName);
+                    LogPrintCategoryOrThreadThrottled(BCLog::STAKING, "init_waiting", 1000 * 60 * 10, "ThreadStaker: (%s) waiting init...\n", operatorName);
                 }
                 else if (status == Staker::Status::stakeWaiting) {
-                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) Staked, but no kernel found yet.\n", operatorName);
+                    LogPrintCategoryOrThreadThrottled(BCLog::STAKING, "no_kernel_found", 1000 * 60 * 10,"ThreadStaker: (%s) Staked, but no kernel found yet.\n", operatorName);
                 }
             }
             catch (const std::runtime_error &e) {

diff --git a/src/pos.cpp b/src/pos.cpp
@@ -204,7 +204,7 @@ boost::optional<std::string> CheckSignedBlock(const std::shared_ptr<CBlock>& pbl
     if (!CheckProofOfStake(*(CBlockHeader*)pblock.get(), pindexPrev,  chainparams.GetConsensus(), pcustomcsview.get()))
         return {std::string{} + "proof-of-stake checking failed"};
 
-    LogPrint(BCLog::STAKING, "new proof-of-stake block found hash: %s\n", hashBlock.GetHex());
+    LogPrintf("new proof-of-stake block found hash: %s\n", hashBlock.GetHex());
 
     // Found a solution
     if (pblock->hashPrevBlock != pindexPrev->GetBlockHash())