From 3bcb787a368cb37d61b3eb7a8c7cfe64d987d3dd Mon Sep 17 00:00:00 2001 From: Ed Hennis Date: Mon, 28 Oct 2024 19:04:52 -0400 Subject: [PATCH 1/2] Add logging ONLY for amendment voting decision process --- src/xrpld/app/consensus/RCLConsensus.cpp | 2 +- src/xrpld/app/misc/AmendmentTable.h | 7 +- src/xrpld/app/misc/detail/AmendmentTable.cpp | 89 +++++++++++++++++--- 3 files changed, 86 insertions(+), 12 deletions(-) diff --git a/src/xrpld/app/consensus/RCLConsensus.cpp b/src/xrpld/app/consensus/RCLConsensus.cpp index 263d660d003..c8dac885321 100644 --- a/src/xrpld/app/consensus/RCLConsensus.cpp +++ b/src/xrpld/app/consensus/RCLConsensus.cpp @@ -354,7 +354,7 @@ RCLConsensus::Adaptor::onClose( { feeVote_->doVoting(prevLedger, validations, initialSet); app_.getAmendmentTable().doVoting( - prevLedger, validations, initialSet); + prevLedger, validations, initialSet, j_); } } else if ( diff --git a/src/xrpld/app/misc/AmendmentTable.h b/src/xrpld/app/misc/AmendmentTable.h index 538d7299f3b..d6193adca2c 100644 --- a/src/xrpld/app/misc/AmendmentTable.h +++ b/src/xrpld/app/misc/AmendmentTable.h @@ -147,7 +147,8 @@ class AmendmentTable doVoting( std::shared_ptr const& lastClosedLedger, std::vector> const& parentValidations, - std::shared_ptr const& initialPosition) + std::shared_ptr const& initialPosition, + beast::Journal j) { // Ask implementation what to do auto actions = doVoting( @@ -174,6 +175,10 @@ class AmendmentTable Serializer s; amendTx.add(s); + JLOG(j.debug()) << "Amendments: Adding pseudo-transaction: " + << amendTx.getTransactionID() << ": " + << strHex(s.slice()) << ": " << amendTx; + initialPosition->addGiveItem( SHAMapNodeType::tnTRANSACTION_NM, make_shamapitem(amendTx.getTransactionID(), s.slice())); diff --git a/src/xrpld/app/misc/detail/AmendmentTable.cpp b/src/xrpld/app/misc/detail/AmendmentTable.cpp index 62b80890821..28bc9d4ab7d 100644 --- a/src/xrpld/app/misc/detail/AmendmentTable.cpp +++ b/src/xrpld/app/misc/detail/AmendmentTable.cpp @@ -25,7 +25,10 @@ #include #include #include + +#include #include +#include #include #include #include @@ -147,6 +150,7 @@ class TrustedVotes Rules const& rules, std::vector> const& valSet, NetClock::time_point const closeTime, + beast::Journal j, std::lock_guard const& lock) { // When we get an STValidation we save the upVotes it contains, but @@ -163,38 +167,86 @@ class TrustedVotes using namespace std::chrono_literals; static constexpr NetClock::duration expiresAfter = 24h; + auto const newTimeout = closeTime + expiresAfter; + // Walk all validations and replace previous votes from trusted // validators with these newest votes. for (auto const& val : valSet) { + auto const pkHuman = + toBase58(TokenType::NodePublic, val->getSignerPublic()); // If this validation comes from one of our trusted validators... if (auto const iter = recordedVotes_.find(val->getSignerPublic()); iter != recordedVotes_.end()) { - iter->second.timeout = closeTime + expiresAfter; + iter->second.timeout = newTimeout; if (val->isFieldPresent(sfAmendments)) { auto const& choices = val->getFieldV256(sfAmendments); iter->second.upVotes.assign(choices.begin(), choices.end()); + JLOG(j.debug()) + << "recordVotes: Validation from trusted " << pkHuman + << " has " << choices.size() << " amendment votes: " + << boost::algorithm::join( + iter->second.upVotes | + boost::adaptors::transformed( + to_string<256, void>), + ", "); + // TODO: Maybe transform using to_short_string once #5126 is + // merged + // + // iter->second.upVotes | + // boost::adaptors::transformed(to_short_string<256, void>) } else { // This validator does not upVote any amendments right now. iter->second.upVotes.clear(); + JLOG(j.debug()) << "recordVotes: Validation from trusted " + << pkHuman << " has no amendment votes."; } } + else + { + JLOG(j.debug()) + << "recordVotes: Ignoring validation from untrusted " + << pkHuman; + } } // Now remove any expired records from recordedVotes_. std::for_each( recordedVotes_.begin(), recordedVotes_.end(), - [&closeTime](decltype(recordedVotes_)::value_type& votes) { + [&closeTime, newTimeout, &j]( + decltype(recordedVotes_)::value_type& votes) { + auto const pkHuman = + toBase58(TokenType::NodePublic, votes.first); if (closeTime > votes.second.timeout) { + JLOG(j.debug()) + << "recordVotes: Timeout: Clearing votes from " + << pkHuman; votes.second.timeout = maxTimeout; votes.second.upVotes.clear(); } + else if (votes.second.timeout == maxTimeout) + { + assert(votes.second.upVotes.empty()); + JLOG(j.debug()) + << "recordVotes: Have not received any " + "amendment votes from " + << pkHuman << " since last timeout or startup"; + } + else if (votes.second.timeout != newTimeout) + { + assert(votes.second.timeout < newTimeout); + using namespace std::chrono; + auto const age = duration_cast( + newTimeout - votes.second.timeout); + JLOG(j.debug()) << "recordVotes: Using " << age.count() + << "min old cached votes from " << pkHuman; + } }); } @@ -787,13 +839,13 @@ AmendmentTableImpl::doVoting( std::lock_guard lock(mutex_); // Keep a record of the votes we received. - previousTrustedVotes_.recordVotes(rules, valSet, closeTime, lock); + previousTrustedVotes_.recordVotes(rules, valSet, closeTime, j_, lock); // Tally the most recent votes. auto vote = std::make_unique(rules, previousTrustedVotes_, lock); - JLOG(j_.debug()) << "Received " << vote->trustedValidations() - << " trusted validations, threshold is: " + JLOG(j_.debug()) << "Counted votes from " << vote->trustedValidations() + << " valid trusted validations, threshold is: " << vote->threshold(); // Map of amendments to the action to be taken for each one. The action is @@ -813,22 +865,27 @@ AmendmentTableImpl::doVoting( majorityTime = it->second; } + std::stringstream ss; + ss << entry.first << " (" << entry.second.name << ") has " + << vote->votes(entry.first) << " votes"; + if (enabledAmendments.count(entry.first) != 0) { - JLOG(j_.debug()) << entry.first << ": amendment already enabled"; + JLOG(j_.trace()) << entry.first << ": amendment already enabled"; } else if ( hasValMajority && (majorityTime == NetClock::time_point{}) && entry.second.vote == AmendmentVote::up) { - // Ledger says no majority, validators say yes - JLOG(j_.debug()) << entry.first << ": amendment got majority"; + // Ledger says no majority, validators say yes, and voting yes + // locally + JLOG(j_.debug()) << ss.str() << ": amendment got majority"; actions[entry.first] = tfGotMajority; } else if (!hasValMajority && (majorityTime != NetClock::time_point{})) { // Ledger says majority, validators say no - JLOG(j_.debug()) << entry.first << ": amendment lost majority"; + JLOG(j_.debug()) << ss.str() << ": amendment lost majority"; actions[entry.first] = tfLostMajority; } else if ( @@ -837,9 +894,21 @@ AmendmentTableImpl::doVoting( entry.second.vote == AmendmentVote::up) { // Ledger says majority held - JLOG(j_.debug()) << entry.first << ": amendment majority held"; + JLOG(j_.debug()) << ss.str() << ": amendment majority held"; actions[entry.first] = 0; } + // Logging only below this point + else if (hasValMajority && (majorityTime != NetClock::time_point{})) + { + JLOG(j_.debug()) + << ss.str() + << ": amendment holding majority, waiting to be enabled"; + } + else if (!hasValMajority) + { + JLOG(j_.debug()) + << ss.str() << ": amendment does not have majority"; + } } // Stash for reporting From f1348b8a1b3a9edc3385da879cd84bfd28b5038e Mon Sep 17 00:00:00 2001 From: Ed Hennis Date: Mon, 28 Oct 2024 19:24:02 -0400 Subject: [PATCH 2/2] Change how "received validations" are counted, and refactoring --- src/xrpld/app/misc/detail/AmendmentTable.cpp | 71 +++++++++++--------- 1 file changed, 41 insertions(+), 30 deletions(-) diff --git a/src/xrpld/app/misc/detail/AmendmentTable.cpp b/src/xrpld/app/misc/detail/AmendmentTable.cpp index 28bc9d4ab7d..5988696b6b9 100644 --- a/src/xrpld/app/misc/detail/AmendmentTable.cpp +++ b/src/xrpld/app/misc/detail/AmendmentTable.cpp @@ -91,15 +91,17 @@ parseSection(Section const& section) class TrustedVotes { private: - static constexpr NetClock::time_point maxTimeout = - NetClock::time_point::max(); - // Associates each trusted validator with the last votes we saw from them // and an expiration for that record. struct UpvotesAndTimeout { std::vector upVotes; - NetClock::time_point timeout = maxTimeout; + /** An unseated timeout indicates that either + 1. No validations have ever been received + 2. The validator has not been heard from in long enough that the + timeout passed, and votes expired. + */ + std::optional timeout; }; hash_map recordedVotes_; @@ -133,7 +135,7 @@ class TrustedVotes else { // New validators have a starting position of no on everything. - // Add the entry with an empty vector and maxTimeout. + // Add the entry with an empty vector and unseated timeout. newRecordedVotes[trusted]; } } @@ -222,15 +224,7 @@ class TrustedVotes decltype(recordedVotes_)::value_type& votes) { auto const pkHuman = toBase58(TokenType::NodePublic, votes.first); - if (closeTime > votes.second.timeout) - { - JLOG(j.debug()) - << "recordVotes: Timeout: Clearing votes from " - << pkHuman; - votes.second.timeout = maxTimeout; - votes.second.upVotes.clear(); - } - else if (votes.second.timeout == maxTimeout) + if (!votes.second.timeout) { assert(votes.second.upVotes.empty()); JLOG(j.debug()) @@ -238,12 +232,20 @@ class TrustedVotes "amendment votes from " << pkHuman << " since last timeout or startup"; } + else if (closeTime > votes.second.timeout) + { + JLOG(j.debug()) + << "recordVotes: Timeout: Clearing votes from " + << pkHuman; + votes.second.timeout.reset(); + votes.second.upVotes.clear(); + } else if (votes.second.timeout != newTimeout) { assert(votes.second.timeout < newTimeout); using namespace std::chrono; auto const age = duration_cast( - newTimeout - votes.second.timeout); + newTimeout - *votes.second.timeout); JLOG(j.debug()) << "recordVotes: Using " << age.count() << "min old cached votes from " << pkHuman; } @@ -257,14 +259,20 @@ class TrustedVotes getVotes(Rules const& rules, std::lock_guard const& lock) const { hash_map ret; + int available = 0; for (auto& validatorVotes : recordedVotes_) { + assert( + validatorVotes.second.timeout || + validatorVotes.second.upVotes.empty()); + if (validatorVotes.second.timeout) + ++available; for (uint256 const& amendment : validatorVotes.second.upVotes) { ret[amendment] += 1; } } - return {recordedVotes_.size(), ret}; + return {available, ret}; } }; @@ -855,26 +863,29 @@ AmendmentTableImpl::doVoting( // process all amendments we know of for (auto const& entry : amendmentMap_) { - NetClock::time_point majorityTime = {}; + if (enabledAmendments.count(entry.first) != 0) + { + JLOG(j_.trace()) << entry.first << ": amendment already enabled"; + + continue; + } bool const hasValMajority = vote->passes(entry.first); - { + auto const majorityTime = [&]() -> std::optional { auto const it = majorityAmendments.find(entry.first); if (it != majorityAmendments.end()) - majorityTime = it->second; - } + return it->second; + return std::nullopt; + }(); + + bool const hasLedgerMajority = majorityTime.has_value(); std::stringstream ss; ss << entry.first << " (" << entry.second.name << ") has " << vote->votes(entry.first) << " votes"; - if (enabledAmendments.count(entry.first) != 0) - { - JLOG(j_.trace()) << entry.first << ": amendment already enabled"; - } - else if ( - hasValMajority && (majorityTime == NetClock::time_point{}) && + if (hasValMajority && !hasLedgerMajority && entry.second.vote == AmendmentVote::up) { // Ledger says no majority, validators say yes, and voting yes @@ -882,15 +893,15 @@ AmendmentTableImpl::doVoting( JLOG(j_.debug()) << ss.str() << ": amendment got majority"; actions[entry.first] = tfGotMajority; } - else if (!hasValMajority && (majorityTime != NetClock::time_point{})) + else if (!hasValMajority && hasLedgerMajority) { // Ledger says majority, validators say no JLOG(j_.debug()) << ss.str() << ": amendment lost majority"; actions[entry.first] = tfLostMajority; } else if ( - (majorityTime != NetClock::time_point{}) && - ((majorityTime + majorityTime_) <= closeTime) && + hasLedgerMajority && + ((*majorityTime + majorityTime_) <= closeTime) && entry.second.vote == AmendmentVote::up) { // Ledger says majority held @@ -898,7 +909,7 @@ AmendmentTableImpl::doVoting( actions[entry.first] = 0; } // Logging only below this point - else if (hasValMajority && (majorityTime != NetClock::time_point{})) + else if (hasValMajority && hasLedgerMajority) { JLOG(j_.debug()) << ss.str()