Account for actual elapsed nomination time in the trigger drift allowance

Integrate the trigger timestamp bookkeeping from 9193e36 and the elapsed-time heuristic from 209e581. Credit steady-clock time through first ballot entry, preserve clock drift fallbacks, and cover slow rounds, delayed callbacks, missing history, and ballot overlap. Keep the existing proposal preparation policy.

Author: SirTyson

src/herder/HerderImpl.cpp

@@ -1301,7 +1301,10 @@ HerderImpl::triggerAnchorFromPrepareStart(
 //
 //   To get a better sense of which, we also take into account
 //   nomination time, so the check becomes timeSinceNetworkLedgerStart > target
-//   + nominationBudget, where nomination budget scales with timeouts.
+//   + nominationBudget. The budget is measured on the steady clock from the
+//   local trigger to entry into ballot. This includes proposal construction
+//   and all nomination time, including unfinished rounds and delayed timer
+//   callbacks.
 //
 //   If we think we're drifting ahead after taking nomination into account, we
 //   fall back to prepare-start anchor, which is based on our local clock and
@@ -1338,8 +1341,8 @@ HerderImpl::triggerAnchorFromPrepareStart(
 //    not because our system clock drifted. The goal is to avoid falling back to
 //    a conservative timer and snowballing the real delay.
 //
-//    See scenario 1, but TL;DR we can look at the nomination timeouts and see
-//    if the network is slow vs. the node drifting. If nomination is slow, we
+//    See scenario 1: measured elapsed time accounts for slow nomination
+//    independently of system clock drift. If nomination is slow, we
 //    can't fall back to the prepare-apply timer because it would compound the
 //    delay. If apply is slow, it doesn't matter which timer we use, they both
 //    will result in triggering immediately.
@@ -1361,14 +1364,9 @@ HerderImpl::triggerAnchorFromConsensusCloseTime(
         return fallbackToPrepareStart();
     }
 
-    // Compare elapsed time on the externalized closeTime timeline with elapsed
-    // time on our local prepare-start timeline.
-    // Relation, with drift > 0 meaning our clock is ahead of network time:
-    //
-    //   timeSinceNetworkLedgerStart
-    //     = nominationBudget + timeSinceLocalBallotStart + drift
-    //
-    // where nominationBudget is the slow-nomination allowance described above.
+    // Compare elapsed time since the externalized closeTime with local steady
+    // time. Their difference includes clock drift and how early or late our
+    // trigger fired relative to the proposer's close time.
     auto externalizedSystemTime = consensusCloseTime.toSystemTime();
     auto currentSystemTime = mApp.getClock().system_now();
     auto timeSinceNetworkLedgerStart =
@@ -1381,29 +1379,39 @@ HerderImpl::triggerAnchorFromConsensusCloseTime(
         std::chrono::duration_cast<std::chrono::milliseconds>(now -
                                                               localBallotStart);
 
+    auto nominationBudget =
+        mHerderSCPDriver.getTriggerToBallotDuration(lastIndex);
+    auto logFallback = [&](char const* reason) {
+        auto zero = std::chrono::milliseconds::zero();
+        CLOG_INFO(
+            Herder,
+            "Trigger fallback after ledger {}: {}, network elapsed {} "
+            "ms, trigger-to-ballot {} ms, ballot elapsed {} ms, local "
+            "wait {} ms, network wait {} ms",
+            lastIndex, reason, timeSinceNetworkLedgerStart.count(),
+            nominationBudget.count(), timeSinceLocalBallotStart.count(),
+            std::max(zero, expectedClose - timeSinceLocalBallotStart).count(),
+            std::max(zero, expectedClose - timeSinceNetworkLedgerStart)
+                .count());
+        return fallbackToPrepareStart();
+    };
+
     // Scenario 2: if system time is behind the local prepare-start timer, the
     // network-based anchor can wedge the node, so use the local fallback.
     if (timeSinceLocalBallotStart > timeSinceNetworkLedgerStart)
     {
-        return fallbackToPrepareStart();
-    }
-
-    // Scenario 1: widen the ahead-drift bound by the slow nomination we can
-    // explain from the previous slot's timeout count.
-    auto nominationTimeouts =
-        mHerderSCPDriver.getNominationTimeouts(lastIndex).value_or(0);
-    auto nominationBudget = std::chrono::milliseconds::zero();
-    for (int64_t round = 1; round <= nominationTimeouts; ++round)
-    {
-        nominationBudget += mHerderSCPDriver.computeTimeout(
-            static_cast<uint32_t>(round), /*isNomination=*/true);
+        return logFallback("clock behind");
     }
 
+    // A timeout counts only after its callback runs, and none are counted
+    // after entry into ballot. A slow fetch or busy main thread can therefore
+    // delay nomination without increasing the count. Measure elapsed time
+    // directly instead of approximating it with completed timeout durations.
     // Scenario 1: if elapsed system time exceeds target plus explainable
     // nomination delay, treat it as clock-ahead drift and use the fallback.
     if (timeSinceNetworkLedgerStart > expectedClose + nominationBudget)
     {
-        return fallbackToPrepareStart();
+        return logFallback("clock ahead or slow ballot/apply");
     }
 
     return now - timeSinceNetworkLedgerStart;
@@ -1864,6 +1872,8 @@ HerderImpl::triggerNextLedger(uint32_t ledgerSeqToTrigger,
         return;
     }
 
+    mHerderSCPDriver.recordNominationTrigger(ledgerSeqToTrigger);
+
     // We pick as next close time the current time unless it's before the last
     // close time. We don't know how much time it will take to reach consensus
     // so this is the most appropriate value to use as closeTime.

src/herder/HerderSCPDriver.cpp

@@ -1522,6 +1522,16 @@ HerderSCPDriver::getExternalizeLag(NodeID const& id) const
     return n->second.GetSnapshot().get75thPercentile();
 }
 
+void
+HerderSCPDriver::recordNominationTrigger(uint64_t slotIndex)
+{
+    auto& timing = mSCPExecutionTimes[slotIndex];
+    if (!timing.mTriggerStart && !timing.mNominationStart)
+    {
+        timing.mTriggerStart = mApp.getClock().now();
+    }
+}
+
 void
 HerderSCPDriver::recordSCPEvent(uint64_t slotIndex, bool isNomination)
 {
@@ -1531,8 +1541,10 @@ HerderSCPDriver::recordSCPEvent(uint64_t slotIndex, bool isNomination)
 
     if (isNomination)
     {
-        timing.mNominationStart =
-            std::make_optional<VirtualClock::time_point>(start);
+        if (!timing.mNominationStart)
+        {
+            timing.mNominationStart = start;
+        }
     }
     else
     {
@@ -2042,6 +2054,25 @@ HerderSCPDriver::getNominationTimeouts(uint64_t slotIndex) const
     return std::nullopt;
 }
 
+std::chrono::milliseconds
+HerderSCPDriver::getTriggerToBallotDuration(uint64_t slotIndex) const
+{
+    auto it = mSCPExecutionTimes.find(slotIndex);
+    if (it != mSCPExecutionTimes.end())
+    {
+        auto const& timing = it->second;
+        if (timing.mTriggerStart && timing.mPrepareStart &&
+            *timing.mPrepareStart > *timing.mTriggerStart)
+        {
+            // Stop at ballot even if a local proposal is still being built.
+            // Ballot and apply are already covered by the fallback anchor.
+            return std::chrono::duration_cast<std::chrono::milliseconds>(
+                *timing.mPrepareStart - *timing.mTriggerStart);
+        }
+    }
+    return std::chrono::milliseconds::zero();
+}
+
 void
 HerderSCPDriver::markSlotAsRestored(uint64_t slotIndex)
 {

src/herder/HerderSCPDriver.h

@@ -57,6 +57,7 @@ class HerderSCPDriver : public SCPDriver
     }
 
     void recordSCPExecutionMetrics(uint64_t slotIndex);
+    void recordNominationTrigger(uint64_t slotIndex);
     void recordSCPEvent(uint64_t slotIndex, bool isNomination);
     void recordSCPExternalizeEvent(uint64_t slotIndex, NodeID const& id,
                                    bool forceUpdateSelf);
@@ -218,6 +219,12 @@ class HerderSCPDriver : public SCPDriver
     // Get the number of nomination timeouts that occurred for a given slot
     std::optional<int64_t> getNominationTimeouts(uint64_t slotIndex) const;
 
+    // Elapsed local time from the trigger through entry into ballot, measured
+    // on the steady clock. Includes construction and incomplete nomination
+    // rounds. Missing timing history does not establish any allowance.
+    std::chrono::milliseconds
+    getTriggerToBallotDuration(uint64_t slotIndex) const;
+
 #ifdef BUILD_TESTS
     RandomEvictionCache<TxSetValidityKey, bool, TxSetValidityKeyHash>&
     getTxSetValidityCache()
@@ -298,6 +305,7 @@ class HerderSCPDriver : public SCPDriver
 
     struct SCPTiming
     {
+        std::optional<VirtualClock::time_point> mTriggerStart;
         std::optional<VirtualClock::time_point> mNominationStart;
         std::optional<VirtualClock::time_point> mPrepareStart;
 

src/herder/test/HerderTests.cpp

@@ -6535,6 +6535,13 @@ namespace stellar
 class EarlyNominationTestAccess
 {
   public:
+    static VirtualClock::time_point
+    triggerAnchor(HerderImpl& herder, uint64_t slot)
+    {
+        return herder.triggerAnchorFromConsensusCloseTime(
+            slot, herder.mApp.getClock().now(), std::chrono::seconds(2));
+    }
+
     static TxSetXDRFrameConstPtr
     prepared(HerderImpl& herder)
     {
@@ -6561,6 +6568,195 @@ class EarlyNominationTestAccess
 };
 }
 
+TEST_CASE("trigger fallback credits elapsed time through nomination",
+          "[herder][trigger-construction]")
+{
+    using namespace std::chrono;
+    struct Scenario
+    {
+        int buildMs;
+        int ballotMs;
+        int closeMs;
+        int clockOffsetMs;
+        bool recordTrigger;
+        int expectedWaitMs;
+        int expectedFallbacks;
+    };
+    auto scenario =
+        GENERATE(Scenario{350, 1900, 2100, 0, true, 0, 0},
+                 Scenario{350, 1900, 2100, 4000, true, 1800, 1},
+                 Scenario{350, 1900, 2100, -4000, true, 1800, 1},
+                 Scenario{350, 1900, 4100, 0, true, 0, 1},
+                 Scenario{350, 1900, 2100, 0, false, 1800, 1},
+                 Scenario{350, 1500, 1700, 0, true, 300, 0},
+                 // A slow first round need not execute a timeout callback
+                 // before entering ballot. Its elapsed time is still real.
+                 Scenario{100, 2000, 2250, 0, true, 0, 0},
+                 // Followers need no construction, but still wait on peers.
+                 Scenario{0, 2250, 2450, 0, true, 0, 0},
+                 // Delayed timer callbacks must not hide elapsed time.
+                 Scenario{100, 6500, 6700, 0, true, 0, 0},
+                 // Long nomination does not excuse arbitrary clock drift.
+                 Scenario{100, 6500, 6700, 10000, true, 1800, 1},
+                 Scenario{100, 6500, 6700, -10000, true, 1800, 1});
+    CAPTURE(scenario.buildMs, scenario.closeMs, scenario.clockOffsetMs,
+            scenario.recordTrigger);
+    VirtualClock clock;
+    auto cfg = getTestConfig();
+    cfg.HTTP_PORT = 0;
+    cfg.MANUAL_CLOSE = true;
+    auto app = createTestApplication(clock, cfg);
+    auto& herder = static_cast<HerderImpl&>(app->getHerder());
+    auto& driver = herder.getHerderSCPDriver();
+    auto const slot = app->getLedgerManager().getLastClosedLedgerNum();
+    auto const ct = VirtualClock::to_time_t(clock.system_now()) + 1000;
+    auto const origin = VirtualClock::from_time_t(ct);
+    clock.setCurrentVirtualTime(origin);
+    StellarValue value;
+    value.closeTime = ct;
+    herder.setTrackingSCPState(slot, value, true);
+    if (scenario.recordTrigger)
+    {
+        driver.recordNominationTrigger(slot);
+    }
+    clock.setCurrentVirtualTime(origin + milliseconds(scenario.buildMs));
+    driver.recordSCPEvent(slot, true);
+    clock.setCurrentVirtualTime(origin + milliseconds(scenario.ballotMs));
+    driver.recordSCPEvent(slot, false);
+    clock.setCurrentVirtualTime(origin + milliseconds(scenario.closeMs));
+    clock.setSystemTimeOffset(milliseconds(scenario.clockOffsetMs));
+    REQUIRE(driver.getNominationTimeouts(slot).value() == 0);
+    REQUIRE(driver.getTriggerToBallotDuration(slot) ==
+            milliseconds(scenario.recordTrigger ? scenario.ballotMs : 0));
+    REQUIRE(driver.getTriggerToBallotDuration(slot + 1) ==
+            milliseconds::zero());
+    auto metrics = app->getMetrics().GetAllMetrics();
+    auto const& fallback = dynamic_cast<medida::Meter const&>(
+        *metrics.at({"scp", "trigger", "prepare-start-fallback"}));
+    auto const before = fallback.count();
+    auto deadline = std::max(
+        clock.now(),
+        EarlyNominationTestAccess::triggerAnchor(herder, slot) + seconds(2));
+    REQUIRE(duration_cast<milliseconds>(deadline - clock.now()).count() ==
+            scenario.expectedWaitMs);
+    REQUIRE(fallback.count() - before == scenario.expectedFallbacks);
+}
+
+TEST_CASE("trigger work is recorded by the proposal path",
+          "[herder][trigger-construction]")
+{
+    using namespace std::chrono;
+    VirtualClock clock;
+    auto cfg = getTestConfig();
+    cfg.HTTP_PORT = 0;
+    cfg.MANUAL_CLOSE = true;
+    cfg.QUORUM_SET.threshold = 2;
+    cfg.QUORUM_SET.validators = {
+        cfg.NODE_SEED.getPublicKey(),
+        SecretKey::pseudoRandomForTesting().getPublicKey()};
+    auto app = createTestApplication(clock, cfg);
+    auto& herder = static_cast<HerderImpl&>(app->getHerder());
+    auto& driver = herder.getHerderSCPDriver();
+    auto const slot = app->getLedgerManager().getLastClosedLedgerNum() + 1;
+    herder.mGetTopTransactionsForTesting = [&](size_t) {
+        // A wall-clock adjustment must not change the measured construction
+        // duration or replace it with a negative interval.
+        clock.setCurrentVirtualTime(clock.now() + milliseconds(400));
+        clock.setSystemTimeOffset(seconds(-1));
+        return std::vector<TransactionEnvelope>{};
+    };
+    herder.triggerNextLedger(slot, true);
+    // Until ballot starts there is no completed interval to credit.
+    REQUIRE(driver.getTriggerToBallotDuration(slot) == milliseconds::zero());
+    clock.setCurrentVirtualTime(clock.now() + milliseconds(100));
+    driver.recordSCPEvent(slot, false);
+    REQUIRE(driver.getTriggerToBallotDuration(slot) == milliseconds(500));
+    clock.setCurrentVirtualTime(clock.now() + seconds(1));
+    driver.recordNominationTrigger(slot);
+    driver.recordSCPEvent(slot, true);
+    REQUIRE(driver.getTriggerToBallotDuration(slot) == milliseconds(500));
+    herder.mGetTopTransactionsForTesting = nullptr;
+}
+
+TEST_CASE("trigger work excludes time after entering ballot",
+          "[herder][trigger-construction]")
+{
+    using namespace std::chrono;
+    VirtualClock clock;
+    auto cfg = getTestConfig();
+    cfg.HTTP_PORT = 0;
+    cfg.MANUAL_CLOSE = true;
+    auto app = createTestApplication(clock, cfg);
+    auto& driver =
+        static_cast<HerderImpl&>(app->getHerder()).getHerderSCPDriver();
+    uint64_t const slot = 100;
+    driver.recordNominationTrigger(slot);
+    clock.setCurrentVirtualTime(clock.now() + milliseconds(100));
+    driver.recordSCPEvent(slot, false);
+    clock.setCurrentVirtualTime(clock.now() + milliseconds(300));
+    driver.recordSCPEvent(slot, true);
+    REQUIRE(driver.getTriggerToBallotDuration(slot) == milliseconds(100));
+    driver.recordSCPEvent(slot + 1, false);
+    clock.setCurrentVirtualTime(clock.now() + milliseconds(100));
+    driver.recordNominationTrigger(slot + 1);
+    driver.recordSCPEvent(slot + 1, true);
+    REQUIRE(driver.getTriggerToBallotDuration(slot + 1) ==
+            milliseconds::zero());
+}
+
+TEST_CASE("trigger allowance is independent of timeout callback ordering",
+          "[herder][trigger-construction]")
+{
+    using namespace std::chrono;
+    auto const ballotBeforeTimeout = GENERATE(false, true);
+    VirtualClock clock;
+    auto cfg = getTestConfig();
+    cfg.HTTP_PORT = 0;
+    cfg.MANUAL_CLOSE = true;
+    auto app = createTestApplication(clock, cfg);
+    auto& herder = static_cast<HerderImpl&>(app->getHerder());
+    auto& driver = herder.getHerderSCPDriver();
+    auto const slot = herder.nextConsensusLedgerIndex();
+    auto const ct = VirtualClock::to_time_t(clock.system_now()) + 1;
+    auto const origin = VirtualClock::from_time_t(ct);
+    clock.setCurrentVirtualTime(origin);
+    driver.recordNominationTrigger(slot);
+    clock.setCurrentVirtualTime(origin + milliseconds(100));
+    driver.recordSCPEvent(slot, true);
+    bool timerFired = false;
+    driver.setupTimer(slot, Slot::NOMINATION_TIMER, seconds(2),
+                      [&] { timerFired = true; });
+
+    // Both events become runnable while the main thread is occupied. Entering
+    // ballot before dispatching the expired timer suppresses its timeout count.
+    clock.setCurrentVirtualTime(origin + milliseconds(2500));
+    if (ballotBeforeTimeout)
+    {
+        driver.recordSCPEvent(slot, false);
+    }
+    for (int i = 0; i < 100 && !timerFired; ++i)
+    {
+        clock.crank(false);
+    }
+    REQUIRE(timerFired);
+    REQUIRE(clock.system_now() == origin + milliseconds(2500));
+    if (!ballotBeforeTimeout)
+    {
+        driver.recordSCPEvent(slot, false);
+    }
+    REQUIRE(driver.getNominationTimeouts(slot) ==
+            (ballotBeforeTimeout ? 0 : 1));
+    REQUIRE(driver.getTriggerToBallotDuration(slot) == milliseconds(2500));
+
+    StellarValue value;
+    value.closeTime = ct;
+    herder.setTrackingSCPState(slot, value, true);
+    clock.setCurrentVirtualTime(origin + milliseconds(2700));
+    REQUIRE(EarlyNominationTestAccess::triggerAnchor(herder, slot) +
+                seconds(2) <=
+            clock.now());
+}
+
 TEST_CASE("prepare nomination before trigger", "[herder][early-nomination]")
 {
     auto const soroban = GENERATE(false, true);