Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 11 commits into from
Mar 18, 2022
Merged

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

Show file tree
Hide file tree
Changes from 7 commits
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
824a95c
Correct loglevel for ThreadStaker (#648)
chrizog Dec 28, 2021
3d2ca99
No debug level for MakeStake kernel found (#648)
chrizog Dec 28, 2021
4bdd206
Merge branch 'master' into feature/masternode-debug-log-output
prasannavl Dec 30, 2021
0b2fb14
Time throttled logging for staker (#648)
chrizog Jan 2, 2022
9ba2dbc
Merge branch 'master' into feature/masternode-debug-log-output
chrizog Jan 3, 2022
36b39c2
Merge branch 'master' into feature/masternode-debug-log-output
Jouzo Jan 5, 2022
1bb9436
Reverse logic in log time throttle filter
chrizog Jan 6, 2022
88e4b01
Simplify throttled logging
chrizog Feb 12, 2022
93cc358
Minor refactors
prasannavl Mar 18, 2022
a23ce82
Merge branch 'master' into feature/masternode-debug-log-output
prasannavl Mar 18, 2022
2a00b18
Merge branch 'master' into feature/masternode-debug-log-output
prasannavl Mar 18, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
47 changes: 47 additions & 0 deletions src/logging.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@

#include <fs.h>
#include <tinyformat.h>
#include <util/time.h>

#include <atomic>
#include <cstdint>
Expand Down Expand Up @@ -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:
std::atomic_uint64_t millis_{0};
std::atomic_uint64_t last_time_millis_{0};

public:
TimeThrottledFilter() = delete;
explicit TimeThrottledFilter(uint64_t millis) : millis_(millis)
{
}

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 false;
}
return true;
}
};

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...);
}
}
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I forgot to mention here, Category should be enabled and not filtered to be shown, the problem is throttle will override disabled category so it should be

if (LogAcceptCategory(category) && !time_throttled_filter.filter()) {
    LogPrintf(args...);
}

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is intended and it's not overriding. The idea above proposed was that if the category is enabled it should log everything (no throttle) for detailed monitoring or debugging.
If the category is not enabled, you get the log throttled (e.g. every 10 minutes), so the debug.log is not flooded but still you get some information sometimes (e.g. the "waiting init" in the staker).

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But if you don't enable the category it should not throttle at all, so that's why we need category enabled + not filtered.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The implementation is intended like that. If the category is enabled you want the full output (= no throttling). If the category is not enabled, it should log throttled (e.g. only every 10 minutes), to still have some information, but don't get a flooded debug.log.

This is what @prasannavl mentioned above:

  • Use a time throttled logger method for staking log, that throttles psuedo actionable info, like waiting reindex, waiting init and
    unlock wallet.
  • Pass all those logs to the time throttled log, and for the time throttled log behaviour, if staking log is enabled, always log. And if it's not, throttle these.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @bvbfan and @prasannavl , do you have any updates on this improvement?
If I rebase to master, can we merge it? Or do you have more comments on it?
Thanks!



#endif // DEFI_LOGGING_H
14 changes: 11 additions & 3 deletions src/miner.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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();

Expand Down Expand Up @@ -960,10 +968,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);
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) {
Expand Down
2 changes: 1 addition & 1 deletion src/pos.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down