diff --git a/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java b/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java
index b2054cd..c7039af 100644
--- a/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java
+++ b/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java
@@ -381,13 +381,18 @@ public final class LeadRollover {
*/
private void runRollover(PendingRollover p, FleetConfig.LeadRollover cfg) {
String lead = p.leadTerminal();
- boolean turnSettled = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds());
- if (!turnSettled) {
- log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) within {}s "
- + "after confirm() — refusing to send /clear at all; the calling lead's "
- + "own turn is still live and clearing it now would destroy live context "
- + "(token={})",
- lead, cfg.turnSettleSeconds(), p.token());
+ long rollStartMillis = nowMillis.getAsLong();
+ TurnSettleResult turnResult = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds());
+ if (!turnResult.settled()) {
+ // fleetd #494 follow-up: this line had the SAME defect as the /clear-timeout line below
+ // — cfg.turnSettleSeconds() is the CONFIGURED budget, not how long this wait actually
+ // ran. Print the measured elapsed time alongside it, labelled, exactly like the /clear
+ // path already does.
+ log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) after "
+ + "confirm() — refusing to send /clear at all; the calling lead's own "
+ + "turn is still live and clearing it now would destroy live context "
+ + "(token={}, configured={}s elapsed={}ms)",
+ lead, p.token(), cfg.turnSettleSeconds(), turnResult.elapsedMillis());
return;
}
@@ -395,15 +400,22 @@ public final class LeadRollover {
// /clear is housekeeping, not a delegated turn, and routing it through Injector wedges the
// pane forever (see this class's javadoc).
agents.send(lead, "/clear");
- boolean clearSettled = waitForClearPickupAndSettle(lead, cfg.clearSettleSeconds());
- if (!clearSettled) {
- log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) within {}s "
- + "after /clear — NOT sending bootstrapText (token={})",
- lead, cfg.clearSettleSeconds(), p.token());
+ ClearSettleResult clearResult = waitForClearPickupAndSettle(lead, cfg.clearSettleSeconds());
+ if (!clearResult.settled()) {
+ // fleetd #494: cfg.clearSettleSeconds() is the CONFIGURED budget, not how long the wait
+ // actually ran — an operator reading only that number wrongly believes it is a measured
+ // duration. Print the measured elapsed time and nudge count alongside it, each labelled,
+ // so the two can be compared at a glance.
+ log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) after "
+ + "/clear — NOT sending bootstrapText (token={}, configured={}s "
+ + "elapsed={}ms nudges={})",
+ lead, p.token(), cfg.clearSettleSeconds(), clearResult.elapsedMillis(),
+ clearResult.nudges());
return;
}
agents.send(lead, cfg.bootstrapTextFor(p.handoverPath()));
- log.info("lead-rollover: rolled token={} lead={}", p.token(), lead);
+ long rollElapsedMillis = nowMillis.getAsLong() - rollStartMillis;
+ log.info("lead-rollover: rolled token={} lead={} elapsedMs={}", p.token(), lead, rollElapsedMillis);
}
/** Drop a pending request without rolling. @return whether a pending request existed for {@code token} */
@@ -475,9 +487,15 @@ public final class LeadRollover {
* gate exists to prevent. Do not "simplify" this back to {@code injectable()}. ({@link
* #waitForClearPickupAndSettle} keeps the same exclusion of {@code BLOCKED}, for the same
* reason, on the second wait.)
+ *
+ * @return a {@link TurnSettleResult} whose {@code settled()} is {@code true} once a real
+ * boundary was observed, {@code false} if {@code settleSeconds} elapses first.
+ * {@code elapsedMillis()} is a MEASURED value from the injected {@link #nowMillis}
+ * clock, never the configured {@code settleSeconds} budget (fleetd #494 follow-up).
*/
- private boolean waitUntilAtTurnBoundary(String target, int settleSeconds) {
- long deadline = nowMillis.getAsLong() + TimeUnit.SECONDS.toMillis(settleSeconds);
+ private TurnSettleResult waitUntilAtTurnBoundary(String target, int settleSeconds) {
+ long startMillis = nowMillis.getAsLong();
+ long deadline = startMillis + TimeUnit.SECONDS.toMillis(settleSeconds);
while (nowMillis.getAsLong() < deadline) {
AgentStatus status;
try {
@@ -488,13 +506,20 @@ public final class LeadRollover {
status = null;
}
if (status == AgentStatus.IDLE || status == AgentStatus.DONE) {
- return true;
+ return new TurnSettleResult(true, nowMillis.getAsLong() - startMillis);
}
settleSleeper.run();
}
- return false;
+ return new TurnSettleResult(false, nowMillis.getAsLong() - startMillis);
}
+ /**
+ * The measured outcome of {@link #waitUntilAtTurnBoundary} — fleetd #494 follow-up. The sibling
+ * of {@link ClearSettleResult} for the FIRST wait, which never nudges, so it carries no nudge
+ * count.
+ */
+ private record TurnSettleResult(boolean settled, long elapsedMillis) {}
+
/**
* The SECOND wait in {@link #runRollover} — after {@code /clear} has been sent, waits for it to
* settle, bounded by {@code settleSeconds}. fleetd #489 — the paste-race fix.
@@ -524,8 +549,9 @@ public final class LeadRollover {
* Claude Code prompt is a no-op, so repeating it is safe;
* the {@code PICKUP_GRACE_POLLS}th consecutive such poll, with {@code WORKING} still never
* observed, releases rather than wedges the roll instead of nudging again — the same
- * choice {@code Injector} makes — and returns {@code true} anyway, logged at {@code info}
- * so an operator can see which path ran;
+ * choice {@code Injector} makes — and returns {@code settled() == true} anyway, logged at
+ * {@code warn} with the measured elapsed time (fleetd #494) so an operator can see which
+ * path ran and how long it actually took;
* once {@code WORKING} has been observed, nudging stops and this instead waits for a real
* {@code working → IDLE/DONE} completion boundary before returning {@code true}.
*
@@ -541,15 +567,20 @@ public final class LeadRollover {
* swallowed and logged at {@code debug}, exactly like {@code Injector.java:437-442} — a failed
* nudge must not abort the roll.
*
- * @return {@code true} once {@code /clear} has settled, or once the nudge budget was exhausted
- * with no pickup ever observed (released rather than wedged); {@code false} if {@code
- * settleSeconds} elapses first — the caller must NOT send {@code bootstrapText} in that
- * case, exactly as before this fix
+ * @return a {@link ClearSettleResult} whose {@code settled()} is {@code true} once {@code
+ * /clear} has settled, or once the nudge budget was exhausted with no pickup ever
+ * observed (released rather than wedged); {@code false} if {@code settleSeconds} elapses
+ * first — the caller must NOT send {@code bootstrapText} in that case, exactly as before
+ * this fix. {@code elapsedMillis()} and {@code nudges()} are MEASURED values (from the
+ * injected {@link #nowMillis} clock and an actual nudge count), never the configured
+ * {@code settleSeconds} budget (fleetd #494).
*/
- private boolean waitForClearPickupAndSettle(String target, int settleSeconds) {
- long deadline = nowMillis.getAsLong() + TimeUnit.SECONDS.toMillis(settleSeconds);
+ private ClearSettleResult waitForClearPickupAndSettle(String target, int settleSeconds) {
+ long startMillis = nowMillis.getAsLong();
+ long deadline = startMillis + TimeUnit.SECONDS.toMillis(settleSeconds);
boolean pickedUp = false; // a WORKING sample has been observed since /clear was sent
int idlePollsAwaitingPickup = 0;
+ int nudges = 0;
while (nowMillis.getAsLong() < deadline) {
AgentStatus status;
try {
@@ -563,26 +594,56 @@ public final class LeadRollover {
pickedUp = true;
} else if (status == AgentStatus.IDLE || status == AgentStatus.DONE) {
if (pickedUp) {
- return true; // a real WORKING -> IDLE/DONE completion boundary
+ // a real WORKING -> IDLE/DONE completion boundary
+ return new ClearSettleResult(true, nowMillis.getAsLong() - startMillis, nudges);
}
if (++idlePollsAwaitingPickup >= PICKUP_GRACE_POLLS) {
- log.info("lead-rollover: /clear on {} was never observed as WORKING after {} "
+ long elapsedMillis = nowMillis.getAsLong() - startMillis;
+ // fleetd #494: this release trades a possibly-unsubmitted /clear for progress
+ // instead of wedging the roll — that trade is deliberate and stays. But it is
+ // also exactly the case that reported false success in the real incident (the
+ // whole roll "succeeded" after 438ms of a 20s budget), so raise it to WARN and
+ // print the MEASURED elapsed time next to the target pane, not just the count.
+ //
+ // fleetd #494 follow-up (2nd pass): BOTH numbers in this line must come from
+ // the loop's own counters, never from the PICKUP_GRACE_POLLS constant.
+ // `idlePollsAwaitingPickup` and `nudges` each have exactly one write site in
+ // this loop, on the same branch, so on this branch they cannot differ from
+ // PICKUP_GRACE_POLLS / PICKUP_GRACE_POLLS - 1 today — no test can prove the
+ // difference on this line, and printing the counters does not change that.
+ // What it does buy: one source of truth instead of two, so a later change to
+ // the loop (an early return, a second increment site, a different exit
+ // condition) cannot leave this message reporting a number the loop no longer
+ // produces. The place where `nudges` genuinely varies with the run — and is
+ // covered by a test that can tell it apart from a constant — is the
+ // /clear-timeout warn in runRollover, which prints clearResult.nudges().
+ log.warn("lead-rollover: /clear on {} was never observed as WORKING after {} "
+ "consecutive IDLE/DONE polls ({} of those were nudged) — "
- + "releasing rather than wedging the roll",
- target, PICKUP_GRACE_POLLS, PICKUP_GRACE_POLLS - 1);
- return true;
+ + "releasing rather than wedging the roll (elapsed={}ms)",
+ target, idlePollsAwaitingPickup, nudges, elapsedMillis);
+ return new ClearSettleResult(true, elapsedMillis, nudges);
}
try {
agents.submit(target); // nudge a raced Enter (CB-113) so /clear actually submits
} catch (RuntimeException e) {
log.debug("lead-rollover: resubmit to {} failed (will retry next poll): {}",
target, e.getMessage());
+ } finally {
+ nudges++; // an attempted nudge, whether or not the submit call itself threw
}
}
// AgentStatus.BLOCKED or UNKNOWN (or an unreadable status, above): neither a pickup
// signal nor a boundary — keep polling without nudging or releasing.
settleSleeper.run();
}
- return false;
+ return new ClearSettleResult(false, nowMillis.getAsLong() - startMillis, nudges);
}
+
+ /**
+ * The measured outcome of {@link #waitForClearPickupAndSettle} — fleetd #494. Carries the
+ * MEASURED elapsed time (from the injected {@link #nowMillis} clock) and nudge count alongside
+ * the settle/timeout decision, so callers can log them instead of the configured budget, which
+ * is not how long the wait actually ran.
+ */
+ private record ClearSettleResult(boolean settled, long elapsedMillis, int nudges) {}
}
diff --git a/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java b/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java
index 6d85796..cda2c64 100644
--- a/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java
+++ b/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java
@@ -1,5 +1,9 @@
package dev.ltms.fleet.lead;
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
import com.fasterxml.jackson.databind.JsonNode;
import dev.ltms.fleet.config.FleetConfig;
import dev.ltms.fleet.herdr.AgentControl;
@@ -9,6 +13,7 @@ import dev.ltms.fleet.herdr.HerdrException;
import org.junit.jupiter.api.DisplayName;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.io.TempDir;
+import org.slf4j.LoggerFactory;
import java.io.IOException;
import java.nio.file.Files;
@@ -854,4 +859,207 @@ class LeadRolloverTest {
assertFalse(bootstrapSent.contains("\"handover.md\""),
"must not name the raw relative configured value in the text actually sent");
}
+
+ // ---- fleetd #494: the log lines must print MEASURED values, never the configured budget --
+
+ private static ListAppender attachLog() {
+ Logger logger = (Logger) LoggerFactory.getLogger(LeadRollover.class);
+ logger.setLevel(Level.DEBUG);
+ ListAppender appender = new ListAppender<>();
+ appender.start();
+ logger.addAppender(appender);
+ return appender;
+ }
+
+ private static void detachLog(ListAppender appender) {
+ ((Logger) LoggerFactory.getLogger(LeadRollover.class)).detachAppender(appender);
+ }
+
+ private static ILoggingEvent lastEventContaining(ListAppender events, String substring) {
+ return events.list.stream()
+ .filter(e -> e.getFormattedMessage().contains(substring))
+ .reduce((_, b) -> b)
+ .orElseThrow(() -> new AssertionError("no log event contained \"" + substring
+ + "\"; got: " + events.list.stream().map(ILoggingEvent::getFormattedMessage).toList()));
+ }
+
+ @Test
+ @DisplayName("[fleetd #494] the /clear-timeout warn line prints the MEASURED elapsed time and "
+ + "nudge count next to the configured budget, never the configured value alone")
+ void clearTimeoutLogPrintsMeasuredElapsedAndNudgesNotJustConfigured() throws IOException {
+ // Idle until /clear is sent, then permanently WORKING (a genuinely stuck /clear that never
+ // reaches a completion boundary) — isolates the SECOND wait exactly like
+ // clearThatNeverSettlesAfterwardsNeverSendsBootstrapText, but with a clock that ADVANCES on
+ // every read so the measured elapsed time is a deterministic, non-zero value distinct from
+ // the configured budget — pinning fleetd #494's fix, not just its absence of a hang.
+ FakeHerdr fake = new FakeHerdr();
+ HerdrClient flipsAfterClear = new HerdrClient() {
+ @Override
+ public JsonNode call(String method, Object params) throws HerdrException {
+ JsonNode result = fake.call(method, params);
+ if ("agent.prompt".equals(method) && String.valueOf(params).contains("/clear")) {
+ fake.agentStatus("working");
+ }
+ return result;
+ }
+
+ @Override
+ public void close() {
+ fake.close();
+ }
+ };
+ Path handover = writeHandover("handover contents");
+ FleetConfig.LeadRollover config =
+ new FleetConfig.LeadRollover(handover.toString(), true, 3600, 20, 1 /*clearSettleSeconds*/, "boot text");
+ AtomicLong clock = new AtomicLong(1_000);
+ LeadRollover rollover = newRollover(flipsAfterClear, config, () -> clock.addAndGet(500));
+
+ ListAppender events = attachLog();
+ try {
+ LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
+ LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
+
+ assertTrue(decision.accepted(), "every synchronous gate passes; the refusal is logged "
+ + "only, deep inside the deferred continuation");
+
+ ILoggingEvent event = lastEventContaining(events, "NOT sending bootstrapText");
+ assertEquals(Level.WARN, event.getLevel());
+ String message = event.getFormattedMessage();
+ assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message);
+ assertTrue(message.contains("elapsed=1500ms"), "must print the MEASURED elapsed time — "
+ + "with this fixture's advancing clock, the wait actually ran 1500ms against a "
+ + "1s(=1000ms) configured budget: " + message);
+ assertTrue(message.contains("nudges=0"), "must print the measured nudge count (0 here — "
+ + "the pane was WORKING throughout, never IDLE/DONE, so no nudge was ever sent): "
+ + message);
+ assertFalse(message.contains("within 1s"), "must not present the configured budget as if "
+ + "it were the measured wait duration: " + message);
+ } finally {
+ detachLog(events);
+ }
+ }
+
+ @Test
+ @DisplayName("[fleetd #494] the /clear pickup-grace release line is WARN (was INFO) and prints "
+ + "the measured elapsed time next to the target pane")
+ void clearGraceReleaseLogIsWarnWithMeasuredElapsed() throws IOException {
+ // Default idle throughout — no WORKING sample is ever observed, so the pickup-grace wait
+ // exhausts PICKUP_GRACE_POLLS and releases rather than wedging (see
+ // clearPickupIsNudgedBeforeBootstrapTextWhenPaneStaysIdle for the un-logged half of this
+ // scenario). A self-advancing clock makes the measured elapsed time deterministic and
+ // provably distinct from a bare poll/nudge count.
+ FakeHerdr herdr = new FakeHerdr();
+ Path handover = writeHandover("handover contents");
+ FleetConfig.LeadRollover config = cfg(handover.toString()); // turnSettleSeconds=clearSettleSeconds=20
+ AtomicLong clock = new AtomicLong(1_000);
+ LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500));
+
+ ListAppender events = attachLog();
+ try {
+ LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
+ LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
+
+ assertTrue(decision.accepted(), "expected approval; got: " + decision.reason()
+ + " / " + decision.detail());
+
+ ILoggingEvent event = lastEventContaining(events, "releasing rather than wedging the roll");
+ assertEquals(Level.WARN, event.getLevel(), "the grace-limit release must be WARN, not "
+ + "INFO — it is exactly the case that reported false success in the real incident "
+ + "this fix comes from (a roll that 'succeeded' after 438ms of a 20s budget)");
+ String message = event.getFormattedMessage();
+ assertTrue(message.contains(LEAD), "must name the target pane: " + message);
+ assertTrue(message.contains("elapsed=4500ms"), "must print the MEASURED elapsed time — "
+ + "with this fixture's advancing clock, the wait ran 4500ms before releasing: "
+ + message);
+ // fleetd #494 follow-up (2nd pass): both numbers here are DELIBERATE plain literals,
+ // not derived from LeadRollover.PICKUP_GRACE_POLLS. A version of this assertion that
+ // reads "(" + (LeadRollover.PICKUP_GRACE_POLLS - 1) + " of those were nudged)" builds
+ // its expectation the same way the production code used to build the log line, so it
+ // cannot tell a fixed constant apart from the measured counter — proved by reverting
+ // the production fix and re-running: that mutant stayed green under the old assertion.
+ // If PICKUP_GRACE_POLLS ever changes, THIS TEST MUST FAIL and a human must look at the
+ // new message and update the literals below, not just re-derive them.
+ assertTrue(message.contains("after 8 consecutive IDLE/DONE polls (7 of those were nudged)"),
+ "must print the measured poll count and nudge count as plain numbers, not the "
+ + "PICKUP_GRACE_POLLS constant standing in for either: " + message);
+ } finally {
+ detachLog(events);
+ }
+ }
+
+ @Test
+ @DisplayName("[fleetd #494] the success line prints the measured elapsed time for the whole roll")
+ void successLogPrintsMeasuredElapsedForTheWholeRoll() throws IOException {
+ // Same fixture as clearGraceReleaseLogIsWarnWithMeasuredElapsed: default idle throughout, so
+ // the grace release fires and the roll still goes on to send bootstrapText and log success.
+ // This is deliberately the SAME shape as the real incident (a roll that "succeeds" quickly)
+ // — the missing signal was the elapsed time on this exact line.
+ FakeHerdr herdr = new FakeHerdr();
+ Path handover = writeHandover("handover contents");
+ FleetConfig.LeadRollover config = cfg(handover.toString());
+ AtomicLong clock = new AtomicLong(1_000);
+ LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500));
+
+ ListAppender events = attachLog();
+ try {
+ LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
+ LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
+
+ assertTrue(decision.accepted(), "expected approval; got: " + decision.reason()
+ + " / " + decision.detail());
+
+ ILoggingEvent event = lastEventContaining(events, "lead-rollover: rolled");
+ assertEquals(Level.INFO, event.getLevel());
+ String message = event.getFormattedMessage();
+ // fleetd #494 follow-up: waitUntilAtTurnBoundary now also reads the injected clock one
+ // extra time (to compute ITS OWN measured elapsed on the success path), so the shared
+ // fixture clock advances by one more 500ms tick before the roll finishes than it did
+ // before that follow-up — 7000ms, not 6500ms.
+ assertTrue(message.contains("elapsedMs=7000"), "must print the MEASURED elapsed time for "
+ + "the whole roll — with this fixture's advancing clock, the full roll (turn-settle "
+ + "wait + /clear wait + bootstrapText) took 7000ms: " + message);
+ } finally {
+ detachLog(events);
+ }
+ }
+
+ @Test
+ @DisplayName("[fleetd #494 follow-up] the turn-settle timeout warn line prints the MEASURED "
+ + "elapsed time next to the configured budget, never the configured value alone")
+ void turnTimeoutLogPrintsMeasuredElapsedNotJustConfigured() throws IOException {
+ // The brief that named the four items this ticket fixed left this exact sibling line out —
+ // "did not reach a turn boundary (IDLE or DONE) within {}s after confirm()" — even though it
+ // has the identical defect shape one method below. Same fixture shape as
+ // clearTimeoutLogPrintsMeasuredElapsedAndNudgesNotJustConfigured, but for the FIRST wait: the
+ // calling lead's own pane never goes idle, so waitUntilAtTurnBoundary times out.
+ FakeHerdr herdr = new FakeHerdr();
+ herdr.agentStatus("working"); // the calling lead's own pane — never goes idle in this test
+ Path handover = writeHandover("handover contents");
+ FleetConfig.LeadRollover config =
+ new FleetConfig.LeadRollover(handover.toString(), true, 3600, 1 /*turnSettleSeconds*/, 20, "text");
+ AtomicLong clock = new AtomicLong(1_000);
+ LeadRollover rollover = newRollover(herdr, config, () -> clock.addAndGet(500));
+
+ ListAppender events = attachLog();
+ try {
+ LeadRollover.PendingRollover pending = rollover.open(LEAD, "context is full");
+ LeadRollover.RollDecision decision = rollover.confirm(LEAD, pending.token(), true);
+
+ assertTrue(decision.accepted(), "every synchronous gate should pass; the refusal happens "
+ + "only inside the deferred continuation, which this test's synchronous runner "
+ + "has already run to completion by the time confirm() returns");
+
+ ILoggingEvent event = lastEventContaining(events, "refusing to send /clear at all");
+ assertEquals(Level.WARN, event.getLevel());
+ String message = event.getFormattedMessage();
+ assertTrue(message.contains("configured=1s"), "must label the configured budget: " + message);
+ assertTrue(message.contains("elapsed=1500ms"), "must print the MEASURED elapsed time — "
+ + "with this fixture's advancing clock, the wait actually ran 1500ms against a "
+ + "1s(=1000ms) configured budget: " + message);
+ assertFalse(message.contains("within 1s"), "must not present the configured budget as if "
+ + "it were the measured wait duration: " + message);
+ } finally {
+ detachLog(events);
+ }
+ }
}