From 3fb331145a729b1da61121a7e211442b668e36d8 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 12 Sep 2026 09:08:04 +0700 Subject: [PATCH] fleetd #494: log measured elapsed time, never the configured budget, on a lead-rollover failure/success MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - runRollover's /clear-timeout warn now prints configured/elapsed/nudges, each labelled, instead of presenting cfg.clearSettleSeconds() as if it were the measured wait. - waitForClearPickupAndSettle's pickup-grace release is now log.warn (was log.info) and prints the measured elapsed time next to the target pane — this is the exact path that reported a false-success roll in the real incident (438ms of a 20s budget). - The success line ('lead-rollover: rolled') now prints the measured elapsed time for the whole roll. - waitForClearPickupAndSettle now returns a ClearSettleResult(settled, elapsedMillis, nudges) instead of a bare boolean, so callers can log the measured values instead of the config. - No behaviour change: same sends, same order, same release/refuse decisions. - Adds 3 tests to LeadRolloverTest pinning the content of each changed log line, using a self-advancing fake clock so the measured elapsed/nudge values are deterministic and provably distinct from the configured budget. --- .../dev/ltms/fleet/lead/LeadRollover.java | 71 +++++--- .../dev/ltms/fleet/lead/LeadRolloverTest.java | 153 ++++++++++++++++++ 2 files changed, 204 insertions(+), 20 deletions(-) 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..b521940 100644 --- a/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java +++ b/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java @@ -381,6 +381,7 @@ public final class LeadRollover { */ private void runRollover(PendingRollover p, FleetConfig.LeadRollover cfg) { String lead = p.leadTerminal(); + long rollStartMillis = nowMillis.getAsLong(); boolean turnSettled = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds()); if (!turnSettled) { log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) within {}s " @@ -395,15 +396,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} */ @@ -524,8 +532,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 +550,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 +577,43 @@ 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. + 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, PICKUP_GRACE_POLLS, PICKUP_GRACE_POLLS - 1, 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..16e021c 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,152 @@ 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); + } 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(); + assertTrue(message.contains("elapsedMs=6500"), "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 6500ms: " + message); + } finally { + detachLog(events); + } + } }