From c87cc25aa6575020d3f579905218f7d8925c02a3 Mon Sep 17 00:00:00 2001 From: Dai Ha Date: Sat, 12 Sep 2026 09:22:19 +0700 Subject: [PATCH] fleetd #494 follow-up: print the measured nudge count, and fix the sibling turn-settle timeout line MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - waitForClearPickupAndSettle's grace-release warn now prints the measured 'nudges' counter instead of the constant PICKUP_GRACE_POLLS - 1. The two happen to agree today, but the constant expression was wrong once before (printed PICKUP_GRACE_POLLS itself, claiming 8 nudges where 7 went out) and a code read did not catch it — only a mutation test did. Printing the counter cannot drift from the loop's real behaviour. - waitUntilAtTurnBoundary (the FIRST wait, ~line 386-391) had the identical 'configured value printed as if measured' defect as the three lines fixed in the original #494 commit, but was out of scope because the brief named specific lines instead of the shape. Fixed the same way: it now returns a TurnSettleResult(settled, elapsedMillis) instead of a bare boolean, and the timeout warn prints 'configured={}s elapsed={}ms' instead of presenting cfg.turnSettleSeconds() as the measured wait. - No behaviour change: same sends, same order, same release/refuse decisions. - Test additions: clearGraceReleaseLogIsWarnWithMeasuredElapsed now also asserts the measured nudge count; successLogPrintsMeasuredElapsedForTheWholeRoll's expected elapsed value is updated (7000ms, not 6500ms) to account for waitUntilAtTurnBoundary's own new clock read; a new turnTimeoutLogPrintsMeasuredElapsedNotJustConfigured test pins the sibling line. - Proved the nudges fix with a temporary mutation: set PICKUP_GRACE_POLLS to 5, confirmed via two greps that the mutant applied and the original constant was gone, ran the grace-release test and read the actual log line — nudge count followed to 4 (= 5 - 1), then restored to 8 and reran the full LeadRolloverTest suite as a control (33/33 green). --- .../dev/ltms/fleet/lead/LeadRollover.java | 50 +++++++++++++---- .../dev/ltms/fleet/lead/LeadRolloverTest.java | 56 ++++++++++++++++++- 2 files changed, 92 insertions(+), 14 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 b521940..f5c9587 100644 --- a/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java +++ b/fleetd/src/main/java/dev/ltms/fleet/lead/LeadRollover.java @@ -382,13 +382,17 @@ 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 " - + "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()); + 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; } @@ -483,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 { @@ -496,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. @@ -587,10 +604,19 @@ public final class LeadRollover { // 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: the nudge count printed here must be the MEASURED + // `nudges` counter, never the constant `PICKUP_GRACE_POLLS - 1` — the constant + // happens to equal it today (this branch only fires after exactly + // PICKUP_GRACE_POLLS - 1 nudges), but a mutation test caught this exact + // expression once already printing the wrong constant (PICKUP_GRACE_POLLS + // itself, claiming 8 nudges where 7 went out) and a plain code read did not + // catch it. Printing the counter cannot drift from the loop's real behaviour, + // whatever changes later to PICKUP_GRACE_POLLS or the loop itself. 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 (elapsed={}ms)", - target, PICKUP_GRACE_POLLS, PICKUP_GRACE_POLLS - 1, elapsedMillis); + target, PICKUP_GRACE_POLLS, nudges, elapsedMillis); return new ClearSettleResult(true, elapsedMillis, nudges); } try { 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 16e021c..cfbc813 100644 --- a/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java +++ b/fleetd/src/test/java/dev/ltms/fleet/lead/LeadRolloverTest.java @@ -971,6 +971,14 @@ class LeadRolloverTest { 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: the nudge count in this line must be the MEASURED counter, not + // the constant PICKUP_GRACE_POLLS - 1 that used to stand in for it — the two happen to + // agree today, but only the counter cannot drift from the loop's real behaviour if + // PICKUP_GRACE_POLLS or the loop ever changes. Reference the constant here (rather than + // hardcoding "7") so this assertion itself does not silently stop discriminating if + // PICKUP_GRACE_POLLS changes later. + assertTrue(message.contains("(" + (LeadRollover.PICKUP_GRACE_POLLS - 1) + " of those were nudged)"), + "must print the measured nudge count: " + message); } finally { detachLog(events); } @@ -1000,9 +1008,53 @@ class LeadRolloverTest { 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 " + // 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 6500ms: " + message); + + "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); }