Better/more logging for DKGs (#3381)

* Better/more logging for DKGs

* Use type name instead of type number in CDKGLogger
This commit is contained in:
Alexander Block 2020-03-26 13:25:01 +01:00 committed by GitHub
parent 80be2520a2
commit 17ece14f40
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 42 additions and 13 deletions

View File

@ -60,12 +60,12 @@ static bool ShouldSimulateError(const std::string& type)
}
CDKGLogger::CDKGLogger(const CDKGSession& _quorumDkg, const std::string& _func) :
CDKGLogger(_quorumDkg.params.type, _quorumDkg.pindexQuorum->GetBlockHash(), _quorumDkg.pindexQuorum->nHeight, _quorumDkg.AreWeMember(), _func)
CDKGLogger(_quorumDkg.params.name, _quorumDkg.pindexQuorum->GetBlockHash(), _quorumDkg.pindexQuorum->nHeight, _quorumDkg.AreWeMember(), _func)
{
}
CDKGLogger::CDKGLogger(Consensus::LLMQType _llmqType, const uint256& _quorumHash, int _height, bool _areWeMember, const std::string& _func) :
CBatchedLogger(BCLog::LLMQ_DKG, strprintf("QuorumDKG(type=%d, height=%d, member=%d, func=%s)", _llmqType, _height, _areWeMember, _func))
CDKGLogger::CDKGLogger(const std::string& _llmqTypeName, const uint256& _quorumHash, int _height, bool _areWeMember, const std::string& _func) :
CBatchedLogger(BCLog::LLMQ_DKG, strprintf("QuorumDKG(type=%s, height=%d, member=%d, func=%s)", _llmqTypeName, _height, _areWeMember, _func))
{
}
@ -90,10 +90,6 @@ CDKGMember::CDKGMember(CDeterministicMNCPtr _dmn, size_t _idx) :
bool CDKGSession::Init(const CBlockIndex* _pindexQuorum, const std::vector<CDeterministicMNCPtr>& mns, const uint256& _myProTxHash)
{
if (mns.size() < params.minSize) {
return false;
}
pindexQuorum = _pindexQuorum;
members.resize(mns.size());
@ -119,12 +115,17 @@ bool CDKGSession::Init(const CBlockIndex* _pindexQuorum, const std::vector<CDete
}
}
CDKGLogger logger(*this, __func__);
if (mns.size() < params.minSize) {
logger.Batch("not enough members (%d < %d), aborting init", mns.size(), params.minSize);
return false;
}
if (!myProTxHash.IsNull()) {
quorumDKGDebugManager->InitLocalSessionStatus(params.type, pindexQuorum->GetBlockHash(), pindexQuorum->nHeight);
}
CDKGLogger logger(*this, __func__);
if (myProTxHash.IsNull()) {
logger.Batch("initialized as observer. mns=%d", mns.size());
} else {

View File

@ -30,7 +30,7 @@ class CDKGLogger : public CBatchedLogger
{
public:
CDKGLogger(const CDKGSession& _quorumDkg, const std::string& _func);
CDKGLogger(Consensus::LLMQType _llmqType, const uint256& _quorumHash, int _height, bool _areWeMember, const std::string& _func);
CDKGLogger(const std::string& _llmqTypeName, const uint256& _quorumHash, int _height, bool _areWeMember, const std::string& _func);
};
class CDKGContribution

View File

@ -121,9 +121,13 @@ void CDKGSessionHandler::UpdatedBlockTip(const CBlockIndex* pindexNew)
bool fNewPhase = (quorumStageInt % params.dkgPhaseBlocks) == 0;
int phaseInt = quorumStageInt / params.dkgPhaseBlocks + 1;
QuorumPhase oldPhase = phase;
if (fNewPhase && phaseInt >= QuorumPhase_Initialized && phaseInt <= QuorumPhase_Idle) {
phase = static_cast<QuorumPhase>(phaseInt);
}
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionHandler::%s -- %s - currentHeight=%d, quorumHeight=%d, oldPhase=%d, newPhase=%d\n", __func__,
params.name, currentHeight, quorumHeight, oldPhase, phase);
}
void CDKGSessionHandler::ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStream& vRecv, CConnman& connman)
@ -155,7 +159,7 @@ bool CDKGSessionHandler::InitNewQuorum(const CBlockIndex* pindexQuorum)
auto mns = CLLMQUtils::GetAllQuorumMembers(params.type, pindexQuorum);
if (!curSession->Init(pindexQuorum, mns, activeMasternodeInfo.proTxHash)) {
LogPrintf("CDKGSessionManager::%s -- quorum initialiation failed\n", __func__);
LogPrintf("CDKGSessionManager::%s -- quorum initialiation failed for %s\n", __func__, curSession->params.name);
return false;
}
@ -176,18 +180,23 @@ void CDKGSessionHandler::WaitForNextPhase(QuorumPhase curPhase,
const uint256& expectedQuorumHash,
const WhileWaitFunc& runWhileWaiting)
{
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - starting, curPhase=%d, nextPhase=%d\n", __func__, params.name, curPhase, nextPhase);
while (true) {
if (stopRequested || ShutdownRequested()) {
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - aborting due to stop/shutdown requested\n", __func__, params.name);
throw AbortPhaseException();
}
auto p = GetPhaseAndQuorumHash();
if (!expectedQuorumHash.IsNull() && p.second != expectedQuorumHash) {
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - aborting due unexpected expectedQuorumHash change\n", __func__, params.name);
throw AbortPhaseException();
}
if (p.first == nextPhase) {
break;
}
if (curPhase != QuorumPhase_None && p.first != curPhase) {
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - aborting due unexpected phase change\n", __func__, params.name);
throw AbortPhaseException();
}
if (!runWhileWaiting()) {
@ -195,6 +204,8 @@ void CDKGSessionHandler::WaitForNextPhase(QuorumPhase curPhase,
}
}
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - done, curPhase=%d, nextPhase=%d\n", __func__, params.name, curPhase, nextPhase);
if (nextPhase == QuorumPhase_Initialized) {
quorumDKGDebugManager->ResetLocalSessionStatus(params.type);
} else {
@ -208,16 +219,21 @@ void CDKGSessionHandler::WaitForNextPhase(QuorumPhase curPhase,
void CDKGSessionHandler::WaitForNewQuorum(const uint256& oldQuorumHash)
{
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - starting\n", __func__, params.name);
while (true) {
if (stopRequested || ShutdownRequested()) {
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - aborting due to stop/shutdown requested\n", __func__, params.name);
throw AbortPhaseException();
}
auto p = GetPhaseAndQuorumHash();
if (p.second != oldQuorumHash) {
return;
break;
}
MilliSleep(100);
}
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - done\n", __func__, params.name);
}
// Sleep some time to not fully overload the whole network
@ -255,8 +271,12 @@ void CDKGSessionHandler::SleepBeforePhase(QuorumPhase curPhase,
LOCK(cs);
heightTmp = heightStart = currentHeight;
}
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - starting sleep for %d ms, curPhase=%d\n", __func__, params.name, sleepTime, curPhase);
while (GetTimeMillis() < endTime) {
if (stopRequested || ShutdownRequested()) {
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - aborting due to stop/shutdown requested\n", __func__, params.name);
throw AbortPhaseException();
}
{
@ -272,6 +292,7 @@ void CDKGSessionHandler::SleepBeforePhase(QuorumPhase curPhase,
}
if (phase != curPhase || quorumHash != expectedQuorumHash) {
// Smth went wrong and/or we missed quite a few blocks and it's just too late now
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - aborting due unexpected phase/expectedQuorumHash change\n", __func__, params.name);
throw AbortPhaseException();
}
}
@ -279,6 +300,8 @@ void CDKGSessionHandler::SleepBeforePhase(QuorumPhase curPhase,
MilliSleep(100);
}
}
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - done, curPhase=%d\n", __func__, params.name, curPhase);
}
void CDKGSessionHandler::HandlePhase(QuorumPhase curPhase,
@ -288,9 +311,13 @@ void CDKGSessionHandler::HandlePhase(QuorumPhase curPhase,
const StartPhaseFunc& startPhaseFunc,
const WhileWaitFunc& runWhileWaiting)
{
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - starting, curPhase=%d, nextPhase=%d\n", __func__, params.name, curPhase, nextPhase);
SleepBeforePhase(curPhase, expectedQuorumHash, randomSleepFactor, runWhileWaiting);
startPhaseFunc();
WaitForNextPhase(curPhase, nextPhase, expectedQuorumHash, runWhileWaiting);
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionManager::%s -- %s - done, curPhase=%d, nextPhase=%d\n", __func__, params.name, curPhase, nextPhase);
}
// returns a set of NodeIds which sent invalid messages
@ -550,13 +577,14 @@ void CDKGSessionHandler::PhaseHandlerThread()
{
while (!stopRequested && !ShutdownRequested()) {
try {
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionHandler::%s -- %s - starting HandleDKGRound\n", __func__, params.name);
HandleDKGRound();
} catch (AbortPhaseException& e) {
quorumDKGDebugManager->UpdateLocalSessionStatus(params.type, [&](CDKGDebugSessionStatus& status) {
status.aborted = true;
return true;
});
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionHandler::%s -- aborted current DKG session for llmq=%s\n", __func__, params.name);
LogPrint(BCLog::LLMQ_DKG, "CDKGSessionHandler::%s -- %s - aborted current DKG session\n", __func__, params.name);
}
}
}