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

chrizog · 2021-12-28T18:56:11Z

What kind of PR is this?:

/kind fix

What this PR does / why we need it:

If the option debug="staking" is used, there is too much output in a longer operation of a masternode. The output is flooded with "ThreadStaker: (833......db786ce) waiting init...".
However, if no debug="staking" is used, there is almost no information in the output about newly minted blocks.
The log levels are adjusted, so that "waiting init" is only visible if debug=staking is activated. Without debug=staking it is not shown, but still some important information about newly minted blocks is logged.

Which issue(s) does this PR fixes?:

Fixes #648

Additional comments?:

prasannavl · 2021-12-30T07:22:47Z

Nice! Thank you @chrizog for your contribution. Will review it shortly for minor tweaks, if any and should be good to go after.

prasannavl · 2021-12-30T07:27:10Z

src/miner.cpp

@@ -917,22 +917,22 @@ void ThreadStaker::operator()(std::vector<ThreadStaker::Args> args, CChainParams
            }
            static std::atomic<uint64_t> time{0};
            if (GetSystemTimeInSeconds() - time > 120) {
-                LogPrintf("ThreadStaker: unlock wallet to start minting...\n");
+                LogPrint(BCLog::STAKING, "ThreadStaker: unlock wallet to start minting...\n");


I don't think we want to do this, as this is a user actionable item. If this log is being displayed, it's to prompt to user to either unlock, or remove gen=1 if the intent is not to stake.

prasannavl · 2021-12-30T07:27:56Z

src/miner.cpp

                time = GetSystemTimeInSeconds();
            }
            std::this_thread::sleep_for(std::chrono::milliseconds(100));
        }
    }

-    LogPrintf("ThreadStaker: started.\n");
+    LogPrint(BCLog::STAKING, "ThreadStaker: started.\n");


This is a single log message per staker. Better to leave an auditable log point.

Will change it back

prasannavl · 2021-12-30T07:31:49Z

src/miner.cpp

@@ -793,7 +793,7 @@ namespace pos {
                    {
                        if (shouldIgnoreMint(ctxState.subNode, blockHeight, creationHeight, subNodesBlockTime, chainparams)) 
                            break;
-                        LogPrint(BCLog::STAKING, "MakeStake: kernel found\n");
+                        LogPrintf("MakeStake: kernel found\n");


How about we leave this to staking log, but instead tweak the other (LogPrint(BCLog::STAKING, "ThreadStaker: (%s) minted a block!\n", operatorName);) one to always print since that's more informative?

prasannavl · 2021-12-30T07:32:46Z

src/miner.cpp

@@ -818,7 +818,7 @@ namespace pos {
                    {
                        if (shouldIgnoreMint(ctxState.subNode, blockHeight, creationHeight, subNodesBlockTime, chainparams)) 
                            break;
-                        LogPrint(BCLog::STAKING, "MakeStake: kernel found\n");
+                        LogPrintf("MakeStake: kernel found\n");


Same as above.

prasannavl · 2021-12-30T07:33:51Z

src/miner.cpp

+                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) terminated due to a staking error!\n", operatorName);
                    it = args.erase(it);
                    continue;
                }
                else if (status == Staker::Status::minted) {
-                    LogPrintf("ThreadStaker: (%s) minted a block!\n", operatorName);
+                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) minted a block!\n", operatorName);
                    nMinted[arg.operatorID]++;
                }
                else if (status == Staker::Status::initWaiting) {
-                    LogPrintf("ThreadStaker: (%s) waiting init...\n", operatorName);
+                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) waiting init...\n", operatorName);


How about instead, we keep the first 2 unchanged. However, for the waiting init throttle the log message so there's only one every few mins for waiting init if staking log isn't enabled.

prasannavl · 2021-12-30T07:35:15Z

src/miner.cpp


    while (!args.empty()) {
        boost::this_thread::interruption_point();

        while (fImporting || fReindex) {
            boost::this_thread::interruption_point();

-            LogPrintf("ThreadStaker: waiting reindex...\n");
+            LogPrint(BCLog::STAKING, "ThreadStaker: waiting reindex...\n");


A better approach here would be use a throttled logger method for staking log, that throttles psuedo actionable info, like waiting reindex, waiting init.

prasannavl · 2021-12-30T07:36:34Z

src/miner.cpp

                else if (status == Staker::Status::stakeWaiting) {
                    LogPrint(BCLog::STAKING, "ThreadStaker: (%s) Staked, but no kernel found yet.\n", operatorName);
                }
            }
            catch (const std::runtime_error &e) {
-                LogPrintf("ThreadStaker: (%s) runtime error: %s\n", e.what(), operatorName);
+                LogPrint(BCLog::STAKING, "ThreadStaker: (%s) runtime error: %s\n", e.what(), operatorName);


Again, I believe both of these should be clearly auditable points to verify what happened, either if orphaned txs are used somewhere prematurely or if there was an error.

Will change them back to LogPrintf as before 👍

prasannavl · 2021-12-30T07:42:16Z

Thanks for this. I think a better approach here would be the following:

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.

An alternative that can be quick fix in the meantime:

Switch the non informative ones:

LogPrint(BCLog::STAKING, "MakeStake: kernel found\n");

to staking only.

If the above is done, we can enable this instead of the above:

LogPrintf("New proof-of-stake block found hash: %s\n", hashBlock.GetHex());

Let me know what you think.

chrizog · 2021-12-30T11:50:35Z

Thanks for this. I think a better approach here would be the following:

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.

I totally agree. I would suggest to add a method "LogPrintFiltered(LogFlags, LogFilter, Args..)" to the Logger class. The LogFilter can be a time throttle filter. It would keep the possibility for adding different log filters in the future. I will push an example here, it can be adjusted then.

I will put the PR to WIP and come back then.

Stonygan · 2021-12-30T11:53:58Z

Thanks for this. I think a better approach here would be the following:

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.

An alternative that can be quick fix in the meantime:

Switch the non informative ones:

LogPrint(BCLog::STAKING, "MakeStake: kernel found\n");

to staking only.

If the above is done, we can enable this instead of the above:

LogPrintf("New proof-of-stake block found hash: %s\n", hashBlock.GetHex());

Let me know what you think.

I think the same, all error messages like Wallet unlock or Threadstaker terminated must visible everytime in the Log, not only if a explicit parameter is given.
Threadstaker started is one time message, thats ok when its displayed after the restart of defid.
For me the best way is with debug=staking to write to log:
ThreadStaker: (833......db786ce) waiting init..
ThreadStaker: (833......db786ce) Staked, but no kernel found yet.
and without debug=staking log all whats needed to operate and monitor a masternode:
MakeStake: kernel found
new proof-of-stake block found hash:
ThreadStaker: (833......db786ce) minted a block!
ThreadStaker: waiting reindex...
ThreadStaker: unlock wallet to start minting...
ThreadStaker: started.
ThreadStaker: (%s) terminated due to a staking error

That are all messages which not flood the Log and important to monitor the Node.

The ability to see in the log without "debug=staking" which threadstaker minted the block and which hash it minted is immensely important for us for monitoring, especially when more than one staker is running on a server or a staker is running on more than one server.

chrizog · 2022-01-02T12:00:11Z

As proposed the logs that are not disturbing and only one-time logs are activated again (to Logprintf).

The logs for "waiting init" and "staked but no kernel found yet" are now time throttled and logged at most every 10 minutes for each staker (could be adjusted to less or more minutes).

If debug=staking, then everything is logged immediately without time throttling to have the full information to debug the node.

bvbfan

I like the changes overall

src/logging.h

bvbfan · 2022-01-06T14:12:02Z

src/logging.h

+    // Log everything directly if category is enabled..
+    if (LogAcceptCategory((category))) {
+        LogPrintf(args...);
+    } else { // .. and otherwise time throttle
+        if (!time_throttled_filter.filter()) {
+            LogPrintf(args...);
+        }
+    }
+}


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

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).

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

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.

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!

prasannavl · 2022-02-02T05:45:23Z

Thanks so much @chrizog - this is really good work :) - Sorry for the delay - we had to triage things a bit due to the 2.6.x.

Couple of final thoughts however:

[Edit] Removed irrelevant point that was a misread on my part.

If we indeed go down this path, LogPrintThrottled -> LogPrintCategoryOrThrottled may be better so it's intent is clearer.
One concern I have about the current approach is that, two different messages are throttled under the same filter. What this means is that one of these messages could be swallowed due to the other.
While I really like your abstracted approach here with ILogFilter, I also observed the current way it's done is https://github.com/DeFiCh/ain/pull/1006/files#diff-6bf9d2e37d503f2f3381cd3a41c26e0b9670f26c2cd4571e98d2af9e3767c1a1R926-R930.

So, if we introduce a filter, the filter needs to be able to take this pattern over.

Thinking through the above, I would like you to consider if it's better to simplify it even further than prematurely engineering an abstraction that might never end up getting utilised elsewhere :)

I think using the existing pattern in 3, we can just go ahead merge it right away. While it's admittedly not as "nice" as what you've written, I don't realistically see this being used in many other places at the moment, and if we do, we likely need to give more thought to what the global abstraction has to look like (does the filter need to take the args, does these timed objected need to be held on when the category is on, etc).

prasannavl · 2022-02-02T05:50:35Z

Please disregard the previous note. Thinking further, what I wrote above cannot be applied here. Let me come back on what better options we have here.

prasannavl · 2022-02-02T06:28:12Z

Ok, I do think your approach is a really good way to assimilate with the current code cleanly. However, for the larger abstraction, I think we have two options at this point:

Use a keyed approach. This is going to make the LogPrintCategoryOrThrottled, (actually a better name now would be LogPrintCategoryOrFiltered, since it's abstracted) take another additional key.
Cache the last message inside it, and also let the abstraction pass on args into filter method. The latter part is likely something that's beneficial to do regardless for the abstraction to be flexible.

Use the last key or the last message to compare and decide inside the filter.

prasannavl · 2022-02-02T06:40:53Z

Fastest option however, is to just use https://github.com/DeFiCh/ain/pull/1006/files#diff-6bf9d2e37d503f2f3381cd3a41c26e0b9670f26c2cd4571e98d2af9e3767c1a1R926-R930 pattern with a thread_local variable instead.

Since each staker runs on a different thread, it's already staker scoped.

I'm ok with all of the 3 approaches - though a little less of option 2, since that unnecessarily holds on to the last message.

chrizog · 2022-02-02T16:09:44Z

Hi, I am not sure, if the link from your last comment points to the place you intended. It just points to my files changed in this PR, so I am not sure what you propose as the "fastest option pattern" in your last comment.

chrizog · 2022-02-12T15:38:30Z

The interface was probably engineering too much abstraction. I simplified it a lot now and used the keyed approach with a thread_local map.

prasannavl · 2022-03-18T05:16:11Z

Hi @chrizog - this is fantastic - thank you so much! Sorry for taking so long to come back to this.

Just made some minor tweaks to merging:

Renaming to LogPrintCategoryOrThreadThrottled, so intent is clearer.
Revert message case, to prevent breakage of tool dependencies, if any - even though your casing was the more sensible one. Will add the casing fix to v3 instead :)

prasannavl · 2022-03-18T06:18:33Z

Thank you @chrizog for helping iterate on this. Much appreciated. It's not as elaborate as it was with filter interfaces as you initially conceived - but it's simpler and well contained. When use-cases expand, that would be a nice time to take the approach you have planted the seed for and generalize it. :)

chrizog added 2 commits December 28, 2021 17:41

Correct loglevel for ThreadStaker (DeFiCh#648)

824a95c

No debug level for MakeStake kernel found (DeFiCh#648)

3d2ca99

chrizog requested review from Bushstar, bvbfan, Mixa84, monstrobishi, surangap and uzyn as code owners December 28, 2021 18:56

defichain-bot added the kind/fix label Dec 28, 2021

Merge branch 'master' into feature/masternode-debug-log-output

4bdd206

prasannavl requested changes Dec 30, 2021

View reviewed changes

chrizog changed the title ~~log: Adjust masternode staking output to fix issue #648~~ [WIP] log: Adjust masternode staking output to fix issue #648 Dec 30, 2021

Time throttled logging for staker (DeFiCh#648)

0b2fb14

chrizog changed the title ~~[WIP] log: Adjust masternode staking output to fix issue #648~~ log: Adjust masternode staking output to fix issue #648 Jan 2, 2022

chrizog and others added 2 commits January 3, 2022 18:31

Merge branch 'master' into feature/masternode-debug-log-output

9ba2dbc

Merge branch 'master' into feature/masternode-debug-log-output

36b39c2

bvbfan suggested changes Jan 6, 2022

View reviewed changes

src/logging.h Outdated Show resolved Hide resolved

src/logging.h Outdated Show resolved Hide resolved

src/logging.h Outdated Show resolved Hide resolved

Reverse logic in log time throttle filter

1bb9436

bvbfan reviewed Jan 6, 2022

View reviewed changes

Simplify throttled logging

88e4b01

prasannavl added this to the 2.6.2 milestone Feb 23, 2022

prasannavl added the 2.7.0 label Mar 7, 2022

Minor refactors

93cc358

prasannavl added 2 commits March 18, 2022 10:46

Merge branch 'master' into feature/masternode-debug-log-output

a23ce82

Merge branch 'master' into feature/masternode-debug-log-output

2a00b18

prasannavl merged commit 54557c2 into DeFiCh:master Mar 18, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

chrizog commented Dec 28, 2021 •

edited

Loading

prasannavl commented Dec 30, 2021

prasannavl Dec 30, 2021

prasannavl Dec 30, 2021

chrizog Dec 30, 2021

prasannavl Dec 30, 2021

prasannavl Dec 30, 2021

prasannavl Dec 30, 2021

prasannavl Dec 30, 2021

prasannavl Dec 30, 2021

chrizog Dec 30, 2021

prasannavl commented Dec 30, 2021 •

edited

Loading

chrizog commented Dec 30, 2021

Stonygan commented Dec 30, 2021

chrizog commented Jan 2, 2022

bvbfan left a comment

bvbfan Jan 6, 2022

chrizog Jan 6, 2022

bvbfan Jan 7, 2022

chrizog Jan 8, 2022

chrizog Jan 29, 2022

prasannavl commented Feb 2, 2022 •

edited

Loading

prasannavl commented Feb 2, 2022

prasannavl commented Feb 2, 2022 •

edited

Loading

prasannavl commented Feb 2, 2022 •

edited

Loading

chrizog commented Feb 2, 2022

chrizog commented Feb 12, 2022

prasannavl commented Mar 18, 2022

prasannavl commented Mar 18, 2022

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

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

Conversation

chrizog commented Dec 28, 2021 • edited Loading

What kind of PR is this?:

What this PR does / why we need it:

Which issue(s) does this PR fixes?:

Additional comments?:

prasannavl commented Dec 30, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prasannavl commented Dec 30, 2021 • edited Loading

chrizog commented Dec 30, 2021

Stonygan commented Dec 30, 2021

chrizog commented Jan 2, 2022

bvbfan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

prasannavl commented Feb 2, 2022 • edited Loading

prasannavl commented Feb 2, 2022

prasannavl commented Feb 2, 2022 • edited Loading

prasannavl commented Feb 2, 2022 • edited Loading

chrizog commented Feb 2, 2022

chrizog commented Feb 12, 2022

prasannavl commented Mar 18, 2022

prasannavl commented Mar 18, 2022

chrizog commented Dec 28, 2021 •

edited

Loading

prasannavl commented Dec 30, 2021 •

edited

Loading

prasannavl commented Feb 2, 2022 •

edited

Loading

prasannavl commented Feb 2, 2022 •

edited

Loading

prasannavl commented Feb 2, 2022 •

edited

Loading