From 0b2fb1403f6ec91c4f8c546a57facc58313fd241 Mon Sep 17 00:00:00 2001
From: Christian <christian.herzog3@web.de>
Date: Sun, 2 Jan 2022 12:56:59 +0100
Subject: [PATCH] Time throttled logging for staker (#648)

---
 src/logging.h | 47 +++++++++++++++++++++++++++++++++++++++++++++++
 src/miner.cpp | 30 +++++++++++++++++++-----------
 2 files changed, 66 insertions(+), 11 deletions(-)

diff --git a/src/logging.h b/src/logging.h
index 362e859bc0d..3caebedb194 100644
--- a/src/logging.h
+++ b/src/logging.h
@@ -8,6 +8,7 @@
 
 #include <fs.h>
 #include <tinyformat.h>
+#include <util/time.h>
 
 #include <atomic>
 #include <cstdint>
@@ -167,4 +168,50 @@ static inline void LogPrint(const BCLog::LogFlags& category, const Args&... args
     }
 }
 
+class ILogFilter
+{
+public:
+    virtual ~ILogFilter(){};
+    virtual bool filter() = 0;
+};
+
+// Implementation that logs at most every millis_ milliseconds
+class TimeThrottledFilter : public ILogFilter
+{
+private:
+    uint64_t millis_{0};
+    uint64_t last_time_millis_{0};
+
+public:
+    TimeThrottledFilter() = delete;
+    explicit TimeThrottledFilter(uint64_t millis) : millis_(millis)
+    {
+    }
+
+    virtual bool filter() override
+    {
+        int64_t current_time = GetTimeMillis();
+        // First call or at least millis_ ms to last call
+        if ((last_time_millis_ == 0) || ((current_time - last_time_millis_) > millis_)) {
+            last_time_millis_ = current_time;
+            return true;
+        }
+        return false;
+    }
+};
+
+template <typename... Args>
+static inline void LogPrintThrottled(const BCLog::LogFlags& category, ILogFilter& time_throttled_filter, const Args&... args)
+{
+    // Log everything directly if category is enabled..
+    if (LogAcceptCategory((category))) {
+        LogPrintf(args...);
+    } else { // .. and otherwise time throttle
+        if (time_throttled_filter.filter()) {
+            LogPrintf(args...);
+        }
+    }
+}
+
+
 #endif // DEFI_LOGGING_H
diff --git a/src/miner.cpp b/src/miner.cpp
index 3612180cf71..314661fb092 100644
--- 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>
@@ -793,7 +794,7 @@ namespace pos {
                     {
                         if (shouldIgnoreMint(ctxState.subNode, blockHeight, creationHeight, subNodesBlockTime, chainparams)) 
                             break;
-                        LogPrintf("MakeStake: kernel found\n");
+                        LogPrint(BCLog::STAKING, "MakeStake: kernel found\n");
 
                         found = true;
                         break;
@@ -818,7 +819,7 @@ namespace pos {
                     {
                         if (shouldIgnoreMint(ctxState.subNode, blockHeight, creationHeight, subNodesBlockTime, chainparams)) 
                             break;
-                        LogPrintf("MakeStake: kernel found\n");
+                        LogPrint(BCLog::STAKING, "MakeStake: kernel found\n");
 
                         found = true;
                         break;
@@ -898,6 +899,13 @@ void ThreadStaker::operator()(std::vector<ThreadStaker::Args> args, CChainParams
 
     std::map<CKeyID, int32_t> nMinted;
     std::map<CKeyID, int32_t> nTried;
+    std::map<CKeyID, std::unique_ptr<ILogFilter>> timeThrottledLogFilter;
+
+
+    for (auto it = args.begin(); it != args.end();) {
+        timeThrottledLogFilter[it->operatorID] = MakeUnique<TimeThrottledFilter>(1000 * 60 * 10); // logs at most every 10 minutes
+        ++it;
+    }
 
     auto wallets = GetWallets();
 
@@ -917,14 +925,14 @@ void ThreadStaker::operator()(std::vector<ThreadStaker::Args> args, CChainParams
             }
             static std::atomic<uint64_t> time{0};
             if (GetSystemTimeInSeconds() - time > 120) {
-                LogPrint(BCLog::STAKING, "ThreadStaker: unlock wallet to start minting...\n");
+                LogPrintf("ThreadStaker: unlock wallet to start minting...\n");
                 time = GetSystemTimeInSeconds();
             }
             std::this_thread::sleep_for(std::chrono::milliseconds(100));
         }
     }
 
-    LogPrint(BCLog::STAKING, "ThreadStaker: started.\n");
+    LogPrintf("ThreadStaker: started.\n");
 
     while (!args.empty()) {
         boost::this_thread::interruption_point();
@@ -932,7 +940,7 @@ void ThreadStaker::operator()(std::vector<ThreadStaker::Args> args, CChainParams
         while (fImporting || fReindex) {
             boost::this_thread::interruption_point();
 
-            LogPrint(BCLog::STAKING, "ThreadStaker: waiting reindex...\n");
+            LogPrintf("ThreadStaker: waiting reindex...\n");
 
             std::this_thread::sleep_for(std::chrono::milliseconds(900));
         }
@@ -951,23 +959,23 @@ void ThreadStaker::operator()(std::vector<ThreadStaker::Args> args, CChainParams
                     status = staker.stake(chainparams, arg);
                 }
                 if (status == Staker::Status::error) {
-                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) terminated due to a staking error!\n", operatorName);
+                    LogPrintf("ThreadStaker: (%s) terminated due to a staking error!\n", operatorName);
                     it = args.erase(it);
                     continue;
                 }
                 else if (status == Staker::Status::minted) {
-                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) minted a block!\n", operatorName);
+                    LogPrintf("ThreadStaker: (%s) minted a block!\n", operatorName);
                     nMinted[arg.operatorID]++;
                 }
                 else if (status == Staker::Status::initWaiting) {
-                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) waiting init...\n", operatorName);
+                    LogPrintThrottled(BCLog::STAKING, *timeThrottledLogFilter[arg.operatorID], "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);
+                    LogPrintThrottled(BCLog::STAKING, *timeThrottledLogFilter[arg.operatorID], "ThreadStaker: (%s) Staked, but no kernel found yet.\n", operatorName);
                 }
             }
             catch (const std::runtime_error &e) {
-                LogPrint(BCLog::STAKING, "ThreadStaker: (%s) runtime error: %s\n", e.what(), operatorName);
+                LogPrintf("ThreadStaker: (%s) runtime error: %s\n", e.what(), operatorName);
 
                 // Could be failed TX in mempool, wipe mempool and allow loop to continue.
                 LOCK(cs_main);