From b24116a118966af19338c25bb4186d44ddef12f3 Mon Sep 17 00:00:00 2001 From: Ed Hennis Date: Wed, 9 Jul 2025 13:46:24 -0400 Subject: [PATCH] Improve locking, logging, and test output - Add more info to the error message on some failed tests. - Add logging details to SHAMapStoreImp --- src/test/app/SHAMapStore_test.cpp | 52 ++++++++++++++++++++++----- src/xrpld/app/misc/SHAMapStoreImp.cpp | 47 +++++++++++++++--------- 2 files changed, 74 insertions(+), 25 deletions(-) diff --git a/src/test/app/SHAMapStore_test.cpp b/src/test/app/SHAMapStore_test.cpp index 9a6edceb54..6815e8a989 100644 --- a/src/test/app/SHAMapStore_test.cpp +++ b/src/test/app/SHAMapStore_test.cpp @@ -657,6 +657,25 @@ public: Env env{*this, envconfig(onlineDelete)}; + auto& ns = env.app().getNodeStore(); + std::map hashes; + auto storeHash = [&]() { + hashes.emplace( + env.current()->info().seq, env.current()->info().hash); + + auto const& root = + ns.fetchNodeObject(hashes[env.current()->info().seq]); + BEAST_EXPECT(root); + }; + + auto failureMessage = [&](char const* label, + auto expected, + auto actual) { + std::stringstream ss; + ss << label << ": Expected: " << expected << ", Got: " << actual; + return ss.str(); + }; + auto const alice = Account("alice"); env.fund(XRP(1000), alice); env.close(); @@ -713,7 +732,10 @@ public: BEAST_EXPECTS( lm.getCompleteLedgers() == expectedRange(minSeq, deleteSeq, maxSeq), - lm.getCompleteLedgers()); + failureMessage( + "Complete ledgers", + expectedRange(minSeq, deleteSeq, maxSeq), + lm.getCompleteLedgers())); BEAST_EXPECT( lm.missingFromCompleteLedgerRange(minSeq, maxSeq) == 1); @@ -726,11 +748,15 @@ public: // Nothing has changed BEAST_EXPECTS( store.getLastRotated() == lastRotated, - to_string(store.getLastRotated())); + failureMessage( + "lastRotated", lastRotated, store.getLastRotated())); BEAST_EXPECTS( lm.getCompleteLedgers() == expectedRange(minSeq, deleteSeq, maxSeq), - lm.getCompleteLedgers()); + failureMessage( + "Complete ledgers", + expectedRange(minSeq, deleteSeq, maxSeq), + lm.getCompleteLedgers())); using namespace std::chrono_literals; // Close 5 more ledgers, waiting one second in between to @@ -746,11 +772,17 @@ public: // Nothing has changed BEAST_EXPECTS( store.getLastRotated() == lastRotated, - to_string(store.getLastRotated())); + failureMessage( + "lastRotated", + lastRotated, + store.getLastRotated())); BEAST_EXPECTS( lm.getCompleteLedgers() == expectedRange(minSeq, deleteSeq, maxSeq), - lm.getCompleteLedgers()); + failureMessage( + "Complete Ledgers", + expectedRange(minSeq, deleteSeq, maxSeq), + lm.getCompleteLedgers())); std::this_thread::sleep_for(1s); } @@ -766,15 +798,19 @@ public: BEAST_EXPECT(maxSeq != lastRotated + deleteInterval); BEAST_EXPECTS( env.closed()->info().seq == maxSeq, - to_string(env.closed()->info().seq)); + failureMessage("maxSeq", maxSeq, env.closed()->info().seq)); BEAST_EXPECTS( store.getLastRotated() == lastRotated, - to_string(store.getLastRotated())); + failureMessage( + "lastRotated", lastRotated, store.getLastRotated())); std::stringstream expectedRange; expectedRange << minSeq << "-" << maxSeq; BEAST_EXPECTS( lm.getCompleteLedgers() == expectedRange.str(), - lm.getCompleteLedgers()); + failureMessage( + "CompleteLedgers", + expectedRange.str(), + lm.getCompleteLedgers())); BEAST_EXPECT( lm.missingFromCompleteLedgerRange(minSeq, maxSeq) == 0); BEAST_EXPECT( diff --git a/src/xrpld/app/misc/SHAMapStoreImp.cpp b/src/xrpld/app/misc/SHAMapStoreImp.cpp index 6949fb8155..b2db93d833 100644 --- a/src/xrpld/app/misc/SHAMapStoreImp.cpp +++ b/src/xrpld/app/misc/SHAMapStoreImp.cpp @@ -308,11 +308,14 @@ SHAMapStoreImp::run() validatedSeq >= lastRotated + deleteInterval_ && canDelete_ >= lastRotated - 1 && healthWait() == keepGoing; - // Note that this is set after the healthWait() check, so that we don't - // start the rotation until the validated ledger is fully processed. It - // is not guaranteed to be done at this point. It also allows the - // testLedgerGaps unit test to work. - lastGoodValidatedLedger_ = validatedSeq; + { + // Note that this is set after the healthWait() check, so that we + // don't start the rotation until the validated ledger is fully + // processed. It is not guaranteed to be done at this point. It also + // allows the testLedgerGaps unit test to work. + std::unique_lock lock(mutex_); + lastGoodValidatedLedger_ = validatedSeq; + } // will delete up to (not including) lastRotated if (readyToRotate) @@ -387,9 +390,10 @@ SHAMapStoreImp::run() clearCaches(validatedSeq); }); - JLOG(journal_.warn()) << "finished rotation " << validatedSeq - << "s. Complete ledgers: " - << ledgerMaster_->getCompleteLedgers(); + JLOG(journal_.warn()) + << "finished rotation. validatedSeq: " << validatedSeq + << ", lastRotated: " << lastRotated << ". Complete ledgers: " + << ledgerMaster_->getCompleteLedgers(); } } } @@ -655,21 +659,30 @@ SHAMapStoreImp::healthWait() !stop_ && (mode != OperatingMode::FULL || age > ageThreshold_ || numMissing > 0)) { + // this value shouldn't change, so grab it while we have the + // lock + auto const lastGood = lastGoodValidatedLedger_; + lock.unlock(); - JLOG(journal_.warn()) - << "Waiting " << recoveryWaitTime_.count() - << "s for node to stabilize. state: " - << app_.getOPs().strOperatingMode(mode, false) << ". age " - << age.count() << "s. Missing ledgers: " << numMissing - << ". Expect: " << lastGoodValidatedLedger_ << "-" << index - << ". Complete ledgers: " << ledgerMaster_->getCompleteLedgers(); + + auto const stream = mode != OperatingMode::FULL || age > ageThreshold_ + ? journal_.warn() + : journal_.info(); + JLOG(stream) << "Waiting " << recoveryWaitTime_.count() + << "s for node to stabilize. state: " + << app_.getOPs().strOperatingMode(mode, false) << ". age " + << age.count() << "s. Missing ledgers: " << numMissing + << ". Expect: " << lastGood << "-" << index + << ". Complete ledgers: " + << ledgerMaster_->getCompleteLedgers(); std::this_thread::sleep_for(recoveryWaitTime_); index = ledgerMaster_->getValidLedgerIndex(); age = ledgerMaster_->getValidatedLedgerAge(); mode = netOPs_->getOperatingMode(); + numMissing = + ledgerMaster_->missingFromCompleteLedgerRange(lastGood, index); + lock.lock(); - numMissing = ledgerMaster_->missingFromCompleteLedgerRange( - lastGoodValidatedLedger_, index); } lastGoodValidatedLedger_ = index;