From 269008b311796b24a3d88f5846478a0ffd359d1a Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Mon, 2 Nov 2015 06:35:58 -0800 Subject: [PATCH] Better logging of built/validated discrepancies: If we built a different ledger from the one we ultimately validate, log the status of the consensus round. This will make it easier to rule out transaction processing issues as the cause of these discrepancies and generally make them easier to diagnose. --- src/ripple/app/ledger/LedgerHistory.cpp | 48 ++++++++++--------- src/ripple/app/ledger/LedgerHistory.h | 17 ++++--- src/ripple/app/ledger/LedgerMaster.h | 2 +- .../app/ledger/impl/LedgerConsensusImp.cpp | 2 +- src/ripple/app/ledger/impl/LedgerMaster.cpp | 4 +- 5 files changed, 40 insertions(+), 33 deletions(-) diff --git a/src/ripple/app/ledger/LedgerHistory.cpp b/src/ripple/app/ledger/LedgerHistory.cpp index 8f3bd98e56..6c2881bf74 100644 --- a/src/ripple/app/ledger/LedgerHistory.cpp +++ b/src/ripple/app/ledger/LedgerHistory.cpp @@ -301,7 +301,7 @@ leaves (SHAMap const& sm) void LedgerHistory::handleMismatch ( - LedgerHash const& built, LedgerHash const& valid) + LedgerHash const& built, LedgerHash const& valid, Json::Value const& consensus) { assert (built != valid); ++mismatch_counter_; @@ -319,6 +319,13 @@ void LedgerHistory::handleMismatch ( assert (builtLedger->info().seq == validLedger->info().seq); + if (j_.debug) + { + j_.debug << "Built: " << getJson (*builtLedger); + j_.debug << "Valid: " << getJson (*validLedger); + j_.debug << "Consensus: " << consensus; + } + // Determine the mismatch reason // Distinguish Byzantine failure from transaction processing difference @@ -384,7 +391,7 @@ void LedgerHistory::handleMismatch ( log_one (validLedger, (*v)->key(), "built", j_); } -void LedgerHistory::builtLedger (Ledger::ref ledger) +void LedgerHistory::builtLedger (Ledger::ref ledger, Json::Value consensus) { LedgerIndex index = ledger->info().seq; LedgerHash hash = ledger->getHash(); @@ -392,20 +399,18 @@ void LedgerHistory::builtLedger (Ledger::ref ledger) ConsensusValidated::ScopedLockType sl ( m_consensus_validated.peekMutex()); - auto entry = std::make_shared>(); + auto entry = std::make_shared(); m_consensus_validated.canonicalize(index, entry, false); - if (entry->first != hash) + if (entry->validated && (entry->validated.get() != hash)) { - if (entry->second.isNonZero() && (entry->second != hash)) - { - JLOG (j_.error) << "MISMATCH: seq=" << index - << " validated:" << entry->second - << " then:" << hash; - handleMismatch (hash, entry->first); - } - entry->first = hash; + JLOG (j_.error) << "MISMATCH: seq=" << index + << " validated:" << entry->validated.get() + << " then:" << hash; + handleMismatch (hash, entry->validated.get(), consensus); } + entry->built.emplace (hash); + entry->consensus.emplace (std::move (consensus)); } void LedgerHistory::validatedLedger (Ledger::ref ledger) @@ -416,21 +421,18 @@ void LedgerHistory::validatedLedger (Ledger::ref ledger) ConsensusValidated::ScopedLockType sl ( m_consensus_validated.peekMutex()); - auto entry = std::make_shared>(); + auto entry = std::make_shared(); m_consensus_validated.canonicalize(index, entry, false); - if (entry->second != hash) + if (entry->built && (entry->built.get() != hash)) { - if (entry->first.isNonZero() && (entry->first != hash)) - { - JLOG (j_.error) << "MISMATCH: seq=" << index - << " built:" << entry->first - << " then:" << hash; - handleMismatch (entry->first, hash); - } - - entry->second = hash; + JLOG (j_.error) << "MISMATCH: seq=" << index + << " built:" << entry->built.get() + << " then:" << hash; + handleMismatch (entry->built.get(), hash, entry->consensus.get()); } + + entry->validated.emplace (hash); } /** Ensure m_ledgers_by_hash doesn't have the wrong hash for a particular index diff --git a/src/ripple/app/ledger/LedgerHistory.h b/src/ripple/app/ledger/LedgerHistory.h index f7a37a7d35..e2a9fe8a22 100644 --- a/src/ripple/app/ledger/LedgerHistory.h +++ b/src/ripple/app/ledger/LedgerHistory.h @@ -83,7 +83,7 @@ public: /** Report that we have locally built a particular ledger */ - void builtLedger (Ledger::ref); + void builtLedger (Ledger::ref, Json::Value); /** Report that we have validated a particular ledger */ @@ -104,8 +104,10 @@ private: validate a different one. @param built The hash of the ledger we built @param valid The hash of the ledger we deemed fully valid + @param consensus The status of the consensus round */ - void handleMismatch (LedgerHash const& built, LedgerHash const& valid); + void handleMismatch (LedgerHash const& built, LedgerHash const& valid, + Json::Value const& consensus); Application& app_; beast::insight::Collector::ptr collector_; @@ -117,10 +119,13 @@ private: // Maps ledger indexes to the corresponding hashes // For debug and logging purposes - // 1) The hash of a ledger with that index we build - // 2) The hash of a ledger with that index we validated - using ConsensusValidated = TaggedCache >; + struct cv_entry + { + boost::optional built; + boost::optional validated; + boost::optional consensus; + }; + using ConsensusValidated = TaggedCache ; ConsensusValidated m_consensus_validated; diff --git a/src/ripple/app/ledger/LedgerMaster.h b/src/ripple/app/ledger/LedgerMaster.h index b9e6bc5096..b160f7d438 100644 --- a/src/ripple/app/ledger/LedgerMaster.h +++ b/src/ripple/app/ledger/LedgerMaster.h @@ -153,7 +153,7 @@ public: virtual void checkAccept (Ledger::ref ledger) = 0; virtual void checkAccept (uint256 const& hash, std::uint32_t seq) = 0; - virtual void consensusBuilt (Ledger::ref ledger) = 0; + virtual void consensusBuilt (Ledger::ref ledger, Json::Value consensus) = 0; virtual LedgerIndex getBuildingLedger () = 0; virtual void setBuildingLedger (LedgerIndex index) = 0; diff --git a/src/ripple/app/ledger/impl/LedgerConsensusImp.cpp b/src/ripple/app/ledger/impl/LedgerConsensusImp.cpp index b8a799e3c2..e399fcc31f 100644 --- a/src/ripple/app/ledger/impl/LedgerConsensusImp.cpp +++ b/src/ripple/app/ledger/impl/LedgerConsensusImp.cpp @@ -1144,7 +1144,7 @@ void LedgerConsensusImp::accept (std::shared_ptr set) << "CNF newLCL " << newLCLHash; // See if we can accept a ledger as fully-validated - ledgerMaster_.consensusBuilt (newLCL); + ledgerMaster_.consensusBuilt (newLCL, getJson (true)); { // Apply disputed transactions that didn't get in diff --git a/src/ripple/app/ledger/impl/LedgerMaster.cpp b/src/ripple/app/ledger/impl/LedgerMaster.cpp index 8e8f006311..b809b40072 100644 --- a/src/ripple/app/ledger/impl/LedgerMaster.cpp +++ b/src/ripple/app/ledger/impl/LedgerMaster.cpp @@ -877,7 +877,7 @@ public: } /** Report that the consensus process built a particular ledger */ - void consensusBuilt (Ledger::ref ledger) override + void consensusBuilt (Ledger::ref ledger, Json::Value consensus) override { // Because we just built a ledger, we are no longer building one @@ -970,7 +970,7 @@ public: checkAccept (maxLedger, maxSeq); } - mLedgerHistory.builtLedger (ledger); + mLedgerHistory.builtLedger (ledger, std::move (consensus)); } void advanceThread()