Skip to content

Commit

Permalink
Make LLMQ/InstantSend/ChainLocks code less spammy (#2781)
Browse files Browse the repository at this point in the history 
* Add support for log category to CBatchedLogger

* Use "llmq" logging category in LLMQ code

* Use "chainlocks" logging category in ChainLocks code

* Log errors without logging category
  • Loading branch information
@codablock
codablock committed Mar 21, 2019
1 parent 591b018 commit b878210
Show file tree
Hide file tree
Showing 10 changed files with 63 additions and 59 deletions.
6 changes: 3 additions & 3 deletions src/batchedlogger.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,8 +5,8 @@
#include "batchedlogger.h"
#include "util.h"

CBatchedLogger::CBatchedLogger(const std::string& _header) :
header(_header)
CBatchedLogger::CBatchedLogger(const std::string& _category, const std::string& _header) :
accept(LogAcceptCategory(_category.c_str())), header(_header)
{
}

Expand All @@ -17,7 +17,7 @@ CBatchedLogger::~CBatchedLogger()

void CBatchedLogger::Flush()
{
if (msg.empty()) {
if (!accept || msg.empty()) {
return;
}
LogPrintStr(strprintf("%s:\n%s", header, msg));
Expand Down
6 changes: 5 additions & 1 deletion src/batchedlogger.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,15 +10,19 @@
class CBatchedLogger
{
private:
bool accept;
std::string header;
std::string msg;
public:
CBatchedLogger(const std::string& _header);
CBatchedLogger(const std::string& _category, const std::string& _header);
virtual ~CBatchedLogger();

template<typename... Args>
void Batch(const std::string& fmt, const Args&... args)
{
if (!accept) {
return;
}
msg += " " + strprintf(fmt, args...) + "\n";
}

Expand Down
18 changes: 9 additions & 9 deletions src/llmq/quorums.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -138,7 +138,7 @@ void CQuorum::StartCachePopulatorThread(std::shared_ptr<CQuorum> _this)
}

cxxtimer::Timer t(true);
LogPrintf("CQuorum::StartCachePopulatorThread -- start\n");
LogPrint("llmq", "CQuorum::StartCachePopulatorThread -- start\n");

// this thread will exit after some time
// when then later some other thread tries to get keys, it will be much faster
Expand All @@ -149,7 +149,7 @@ void CQuorum::StartCachePopulatorThread(std::shared_ptr<CQuorum> _this)
_this->GetPubKeyShare(i);
}
}
LogPrintf("CQuorum::StartCachePopulatorThread -- done. time=%d\n", t.count());
LogPrint("llmq", "CQuorum::StartCachePopulatorThread -- done. time=%d\n", t.count());
});
}

Expand Down Expand Up @@ -205,15 +205,15 @@ void CQuorumManager::EnsureQuorumConnections(Consensus::LLMQType llmqType, const
for (auto& c : connections) {
debugMsg += strprintf(" %s\n", c.ToString(false));
}
LogPrintf(debugMsg);
LogPrint("llmq", debugMsg);
g_connman->AddMasternodeQuorumNodes(llmqType, quorum->quorumHash, connections);
}
}
connmanQuorumsToDelete.erase(quorum->quorumHash);
}

for (auto& qh : connmanQuorumsToDelete) {
LogPrintf("CQuorumManager::%s -- removing masternodes quorum connections for quorum %s:\n", __func__, qh.ToString());
LogPrint("llmq", "CQuorumManager::%s -- removing masternodes quorum connections for quorum %s:\n", __func__, qh.ToString());
g_connman->RemoveMasternodeQuorumNodes(llmqType, qh);
}
}
Expand All @@ -235,7 +235,7 @@ bool CQuorumManager::BuildQuorumFromCommitment(const CFinalCommitment& qc, const
quorum->WriteContributions(evoDb);
hasValidVvec = true;
} else {
LogPrintf("CQuorumManager::%s -- quorum.ReadContributions and BuildQuorumContributions for block %s failed\n", __func__, qc.quorumHash.ToString());
LogPrint("llmq", "CQuorumManager::%s -- quorum.ReadContributions and BuildQuorumContributions for block %s failed\n", __func__, qc.quorumHash.ToString());
}
}

Expand Down Expand Up @@ -264,20 +264,20 @@ bool CQuorumManager::BuildQuorumContributions(const CFinalCommitment& fqc, std::
cxxtimer::Timer t2(true);
quorumVvec = blsWorker.BuildQuorumVerificationVector(vvecs);
if (quorumVvec == nullptr) {
LogPrintf("CQuorumManager::%s -- failed to build quorumVvec\n", __func__);
LogPrint("llmq", "CQuorumManager::%s -- failed to build quorumVvec\n", __func__);
// without the quorum vvec, there can't be a skShare, so we fail here. Failure is not fatal here, as it still
// allows to use the quorum as a non-member (verification through the quorum pub key)
return false;
}
skShare = blsWorker.AggregateSecretKeys(skContributions);
if (!skShare.IsValid()) {
LogPrintf("CQuorumManager::%s -- failed to build skShare\n", __func__);
LogPrint("llmq", "CQuorumManager::%s -- failed to build skShare\n", __func__);
// We don't bail out here as this is not a fatal error and still allows us to recover public key shares (as we
// have a valid quorum vvec at this point)
}
t2.stop();

LogPrintf("CQuorumManager::%s -- built quorum vvec and skShare. time=%d\n", __func__, t2.count());
LogPrint("llmq", "CQuorumManager::%s -- built quorum vvec and skShare. time=%d\n", __func__, t2.count());

quorum->quorumVvec = quorumVvec;
quorum->skShare = skShare;
Expand Down Expand Up @@ -343,7 +343,7 @@ CQuorumCPtr CQuorumManager::GetQuorum(Consensus::LLMQType llmqType, const uint25
auto quorumIt = mapBlockIndex.find(quorumHash);

if (quorumIt == mapBlockIndex.end()) {
LogPrintf("CQuorumManager::%s -- block %s not found", __func__, quorumHash.ToString());
LogPrint("llmq", "CQuorumManager::%s -- block %s not found", __func__, quorumHash.ToString());
return nullptr;
}
pindexQuorum = quorumIt->second;
Expand Down
6 changes: 3 additions & 3 deletions src/llmq/quorums_blockprocessor.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,7 @@ void CQuorumBlockProcessor::ProcessMessage(CNode* pfrom, const std::string& strC

if (!Params().GetConsensus().llmqs.count((Consensus::LLMQType)qc.llmqType)) {
LOCK(cs_main);
LogPrintf("CQuorumBlockProcessor::%s -- invalid commitment type %d from peer=%d\n", __func__,
LogPrintf("llmq""CQuorumBlockProcessor::%s -- invalid commitment type %d from peer=%d\n", __func__,
qc.llmqType, pfrom->id);
Misbehaving(pfrom->id, 100);
return;
Expand Down Expand Up @@ -106,7 +106,7 @@ void CQuorumBlockProcessor::ProcessMessage(CNode* pfrom, const std::string& strC
return;
}

LogPrintf("CQuorumBlockProcessor::%s -- received commitment for quorum %s:%d, validMembers=%d, signers=%d, peer=%d\n", __func__,
LogPrint("llmq", "CQuorumBlockProcessor::%s -- received commitment for quorum %s:%d, validMembers=%d, signers=%d, peer=%d\n", __func__,
qc.quorumHash.ToString(), qc.llmqType, qc.CountValidMembers(), qc.CountSigners(), pfrom->id);

AddMinableCommitment(qc);
Expand Down Expand Up @@ -204,7 +204,7 @@ bool CQuorumBlockProcessor::ProcessCommitment(const CBlockIndex* pindex, const C
hasMinedCommitmentCache.erase(std::make_pair(params.type, quorumHash));
}

LogPrintf("CQuorumBlockProcessor::%s -- processed commitment from block. type=%d, quorumHash=%s, signers=%s, validMembers=%d, quorumPublicKey=%s\n", __func__,
LogPrint("llmq", "CQuorumBlockProcessor::%s -- processed commitment from block. type=%d, quorumHash=%s, signers=%s, validMembers=%d, quorumPublicKey=%s\n", __func__,
qc.llmqType, quorumHash.ToString(), qc.CountSigners(), qc.CountValidMembers(), qc.quorumPublicKey.ToString());

return true;
Expand Down
10 changes: 5 additions & 5 deletions src/llmq/quorums_chainlocks.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -156,7 +156,7 @@ void CChainLocksHandler::ProcessNewChainLock(NodeId from, const llmq::CChainLock
EnforceBestChainLock();
}, 0);

LogPrintf("CChainLocksHandler::%s -- processed new CLSIG (%s), peer=%d\n",
LogPrint("chainlocks", "CChainLocksHandler::%s -- processed new CLSIG (%s), peer=%d\n",
__func__, clsig.ToString(), from);
}

Expand Down Expand Up @@ -244,7 +244,7 @@ void CChainLocksHandler::TrySignChainTip()
}
}

LogPrintf("CChainLocksHandler::%s -- trying to sign %s, height=%d\n", __func__, pindex->GetBlockHash().ToString(), pindex->nHeight);
LogPrint("chainlocks", "CChainLocksHandler::%s -- trying to sign %s, height=%d\n", __func__, pindex->GetBlockHash().ToString(), pindex->nHeight);

// When the new IX system is activated, we only try to ChainLock blocks which include safe transactions. A TX is
// considered safe when it is ixlocked or at least known since 10 minutes (from mempool or block). These checks are
Expand All @@ -256,12 +256,12 @@ void CChainLocksHandler::TrySignChainTip()
if (pindex->nHeight - pindexWalk->nHeight > 5) {
// no need to check further down, 6 confs is safe to assume that TXs below this height won't be
// ixlocked anymore if they aren't already
LogPrintf("CChainLocksHandler::%s -- tip and previous 5 blocks all safe\n", __func__);
LogPrint("chainlocks", "CChainLocksHandler::%s -- tip and previous 5 blocks all safe\n", __func__);
break;
}
if (HasChainLock(pindexWalk->nHeight, pindexWalk->GetBlockHash())) {
// we don't care about ixlocks for TXs that are ChainLocked already
LogPrintf("CChainLocksHandler::%s -- chainlock at height %d \n", __func__, pindexWalk->nHeight);
LogPrint("chainlocks", "CChainLocksHandler::%s -- chainlock at height %d \n", __func__, pindexWalk->nHeight);
break;
}

Expand Down Expand Up @@ -289,7 +289,7 @@ void CChainLocksHandler::TrySignChainTip()
}

if (txAge < WAIT_FOR_ISLOCK_TIMEOUT && !quorumInstantSendManager->IsLocked(txid)) {
LogPrintf("CChainLocksHandler::%s -- not signing block %s due to TX %s not being ixlocked and not old enough. age=%d\n", __func__,
LogPrint("chainlocks", "CChainLocksHandler::%s -- not signing block %s due to TX %s not being ixlocked and not old enough. age=%d\n", __func__,
pindexWalk->GetBlockHash().ToString(), txid.ToString(), txAge);
return;
}
Expand Down
2 changes: 1 addition & 1 deletion src/llmq/quorums_dkgsession.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@ CDKGLogger::CDKGLogger(const CDKGSession& _quorumDkg, const std::string& _func)
}

CDKGLogger::CDKGLogger(Consensus::LLMQType _llmqType, const uint256& _quorumHash, int _height, bool _areWeMember, const std::string& _func) :
CBatchedLogger(strprintf("QuorumDKG(type=%d, height=%d, member=%d, func=%s)", _llmqType, _height, _areWeMember, _func))
CBatchedLogger("llmq", strprintf("QuorumDKG(type=%d, height=%d, member=%d, func=%s)", _llmqType, _height, _areWeMember, _func))
{
}

Expand Down
18 changes: 9 additions & 9 deletions src/llmq/quorums_dkgsessionhandler.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,7 +32,7 @@ void CDKGPendingMessages::PushPendingMessage(NodeId from, CDataStream& vRecv)

if (messagesPerNode[from] >= maxMessagesPerNode) {
// TODO ban?
LogPrint("net", "CDKGPendingMessages::%s -- too many messages, peer=%d\n", __func__, from);
LogPrintf("CDKGPendingMessages::%s -- too many messages, peer=%d\n", __func__, from);
return;
}
messagesPerNode[from]++;
Expand All @@ -45,7 +45,7 @@ void CDKGPendingMessages::PushPendingMessage(NodeId from, CDataStream& vRecv)
LOCK2(cs_main, cs);

if (!seenMessages.emplace(hash).second) {
LogPrint("net", "CDKGPendingMessages::%s -- already seen %s, peer=%d", __func__, from);
LogPrint("llmq", "CDKGPendingMessages::%s -- already seen %s, peer=%d", __func__, from);
return;
}

Expand Down Expand Up @@ -376,7 +376,7 @@ bool ProcessPendingMessageBatch(CDKGSession& session, CDKGPendingMessages& pendi

for (const auto& p : msgs) {
if (!p.second) {
LogPrint("net", "%s -- failed to deserialize message, peer=%d\n", __func__, p.first);
LogPrintf("%s -- failed to deserialize message, peer=%d\n", __func__, p.first);
{
LOCK(cs_main);
Misbehaving(p.first, 100);
Expand All @@ -394,13 +394,13 @@ bool ProcessPendingMessageBatch(CDKGSession& session, CDKGPendingMessages& pendi
bool ban = false;
if (!session.PreVerifyMessage(hash, msg, ban)) {
if (ban) {
LogPrint("net", "%s -- banning node due to failed preverification, peer=%d", __func__, p.first);
LogPrintf("%s -- banning node due to failed preverification, peer=%d", __func__, p.first);
{
LOCK(cs_main);
Misbehaving(p.first, 100);
}
}
LogPrint("net", "%s -- skipping message due to failed preverification, peer=%d", __func__, p.first);
LogPrintf("%s -- skipping message due to failed preverification, peer=%d", __func__, p.first);
continue;
}
hashes.emplace_back(hash);
Expand All @@ -414,7 +414,7 @@ bool ProcessPendingMessageBatch(CDKGSession& session, CDKGPendingMessages& pendi
if (!badNodes.empty()) {
LOCK(cs_main);
for (auto nodeId : badNodes) {
LogPrint("net", "%s -- failed to verify signature, peer=%d", __func__, nodeId);
LogPrintf("%s -- failed to verify signature, peer=%d", __func__, nodeId);
Misbehaving(nodeId, 100);
}
}
Expand All @@ -428,7 +428,7 @@ bool ProcessPendingMessageBatch(CDKGSession& session, CDKGPendingMessages& pendi
bool ban = false;
session.ReceiveMessage(hashes[i], msg, ban);
if (ban) {
LogPrint("net", "%s -- banning node after ReceiveMessage failed, peer=%d", __func__, nodeId);
LogPrintf("%s -- banning node after ReceiveMessage failed, peer=%d", __func__, nodeId);
LOCK(cs_main);
Misbehaving(nodeId, 100);
badNodes.emplace(nodeId);
Expand Down Expand Up @@ -490,7 +490,7 @@ void CDKGSessionHandler::HandleDKGRound()
for (const auto& c : connections) {
debugMsg += strprintf(" %s\n", c.ToString(false));
}
LogPrintf(debugMsg);
LogPrint("llmq", debugMsg);
g_connman->AddMasternodeQuorumNodes(params.type, curQuorumHash, connections);

auto participatingNodesTmp = g_connman->GetMasternodeQuorumAddresses(params.type, curQuorumHash);
Expand Down Expand Up @@ -553,7 +553,7 @@ void CDKGSessionHandler::PhaseHandlerThread()
status.aborted = true;
return true;
});
LogPrintf("CDKGSessionHandler::%s -- aborted current DKG session for llmq=%s\n", __func__, params.name);
LogPrint("llmq", "CDKGSessionHandler::%s -- aborted current DKG session for llmq=%s\n", __func__, params.name);
}
}
}
Expand Down
12 changes: 6 additions & 6 deletions src/llmq/quorums_instantsend.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -212,7 +212,7 @@ bool CInstantSendManager::ProcessTx(const CTransaction& tx, const Consensus::Par
uint256 otherTxHash;
if (quorumSigningManager->GetVoteForId(llmqType, id, otherTxHash)) {
if (otherTxHash != tx.GetHash()) {
LogPrint("instantsend", "CInstantSendManager::%s -- txid=%s: input %s is conflicting with islock %s\n", __func__,
LogPrintf("CInstantSendManager::%s -- txid=%s: input %s is conflicting with islock %s\n", __func__,
tx.GetHash().ToString(), in.prevout.ToStringShort(), otherTxHash.ToString());
return false;
}
Expand Down Expand Up @@ -439,7 +439,7 @@ void CInstantSendManager::HandleNewInstantSendLockRecoveredSig(const llmq::CReco
}

if (islock.txid != recoveredSig.msgHash) {
LogPrint("instantsend", "CInstantSendManager::%s -- txid=%s: islock conflicts with %s, dropping own version", __func__,
LogPrintf("CInstantSendManager::%s -- txid=%s: islock conflicts with %s, dropping own version", __func__,
islock.txid.ToString(), recoveredSig.msgHash.ToString());
return;
}
Expand Down Expand Up @@ -592,7 +592,7 @@ void CInstantSendManager::ProcessPendingInstantSendLocks()
auto& islock = p.second.second;

if (batchVerifier.badMessages.count(hash)) {
LogPrint("instantsend", "CInstantSendManager::%s -- txid=%s, islock=%s: invalid sig in islock, peer=%d\n", __func__,
LogPrintf("CInstantSendManager::%s -- txid=%s, islock=%s: invalid sig in islock, peer=%d\n", __func__,
islock.txid.ToString(), hash.ToString(), nodeId);
continue;
}
Expand Down Expand Up @@ -658,13 +658,13 @@ void CInstantSendManager::ProcessInstantSendLock(NodeId from, const uint256& has
}
otherIsLock = db.GetInstantSendLockByTxid(islock.txid);
if (otherIsLock != nullptr) {
LogPrint("instantsend", "CInstantSendManager::%s -- txid=%s, islock=%s: duplicate islock, other islock=%s, peer=%d\n", __func__,
LogPrintf("CInstantSendManager::%s -- txid=%s, islock=%s: duplicate islock, other islock=%s, peer=%d\n", __func__,
islock.txid.ToString(), hash.ToString(), ::SerializeHash(*otherIsLock).ToString(), from);
}
for (auto& in : islock.inputs) {
otherIsLock = db.GetInstantSendLockByInput(in);
if (otherIsLock != nullptr) {
LogPrint("instantsend", "CInstantSendManager::%s -- txid=%s, islock=%s: conflicting input in islock. input=%s, other islock=%s, peer=%d\n", __func__,
LogPrintf("CInstantSendManager::%s -- txid=%s, islock=%s: conflicting input in islock. input=%s, other islock=%s, peer=%d\n", __func__,
islock.txid.ToString(), hash.ToString(), in.ToStringShort(), ::SerializeHash(*otherIsLock).ToString(), from);
}
}
Expand Down Expand Up @@ -797,7 +797,7 @@ void CInstantSendManager::RemoveMempoolConflictsForLock(const uint256& hash, con
if (it->second->GetHash() != islock.txid) {
toDelete.emplace(it->second->GetHash(), mempool.get(it->second->GetHash()));

LogPrint("instantsend", "CInstantSendManager::%s -- txid=%s, islock=%s: mempool TX %s with input %s conflicts with islock\n", __func__,
LogPrintf("CInstantSendManager::%s -- txid=%s, islock=%s: mempool TX %s with input %s conflicts with islock\n", __func__,
islock.txid.ToString(), hash.ToString(), it->second->GetHash().ToString(), in.ToStringShort());
}
}
Expand Down
Loading

0 comments on commit b878210

Please sign in to comment.