fleetd #494 follow-up: print the measured nudge count, and fix the sibling turn-settle timeout line
- 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).
This commit is contained in:
@@ -382,13 +382,17 @@ public final class LeadRollover {
|
|||||||
private void runRollover(PendingRollover p, FleetConfig.LeadRollover cfg) {
|
private void runRollover(PendingRollover p, FleetConfig.LeadRollover cfg) {
|
||||||
String lead = p.leadTerminal();
|
String lead = p.leadTerminal();
|
||||||
long rollStartMillis = nowMillis.getAsLong();
|
long rollStartMillis = nowMillis.getAsLong();
|
||||||
boolean turnSettled = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds());
|
TurnSettleResult turnResult = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds());
|
||||||
if (!turnSettled) {
|
if (!turnResult.settled()) {
|
||||||
log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) within {}s "
|
// fleetd #494 follow-up: this line had the SAME defect as the /clear-timeout line below
|
||||||
+ "after confirm() — refusing to send /clear at all; the calling lead's "
|
// — cfg.turnSettleSeconds() is the CONFIGURED budget, not how long this wait actually
|
||||||
+ "own turn is still live and clearing it now would destroy live context "
|
// ran. Print the measured elapsed time alongside it, labelled, exactly like the /clear
|
||||||
+ "(token={})",
|
// path already does.
|
||||||
lead, cfg.turnSettleSeconds(), p.token());
|
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;
|
return;
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -483,9 +487,15 @@ public final class LeadRollover {
|
|||||||
* gate exists to prevent. Do not "simplify" this back to {@code injectable()}. ({@link
|
* gate exists to prevent. Do not "simplify" this back to {@code injectable()}. ({@link
|
||||||
* #waitForClearPickupAndSettle} keeps the same exclusion of {@code BLOCKED}, for the same
|
* #waitForClearPickupAndSettle} keeps the same exclusion of {@code BLOCKED}, for the same
|
||||||
* reason, on the second wait.)
|
* 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) {
|
private TurnSettleResult waitUntilAtTurnBoundary(String target, int settleSeconds) {
|
||||||
long deadline = nowMillis.getAsLong() + TimeUnit.SECONDS.toMillis(settleSeconds);
|
long startMillis = nowMillis.getAsLong();
|
||||||
|
long deadline = startMillis + TimeUnit.SECONDS.toMillis(settleSeconds);
|
||||||
while (nowMillis.getAsLong() < deadline) {
|
while (nowMillis.getAsLong() < deadline) {
|
||||||
AgentStatus status;
|
AgentStatus status;
|
||||||
try {
|
try {
|
||||||
@@ -496,13 +506,20 @@ public final class LeadRollover {
|
|||||||
status = null;
|
status = null;
|
||||||
}
|
}
|
||||||
if (status == AgentStatus.IDLE || status == AgentStatus.DONE) {
|
if (status == AgentStatus.IDLE || status == AgentStatus.DONE) {
|
||||||
return true;
|
return new TurnSettleResult(true, nowMillis.getAsLong() - startMillis);
|
||||||
}
|
}
|
||||||
settleSleeper.run();
|
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
|
* The SECOND wait in {@link #runRollover} — after {@code /clear} has been sent, waits for it to
|
||||||
* settle, bounded by {@code settleSeconds}. <strong>fleetd #489 — the paste-race fix.</strong>
|
* settle, bounded by {@code settleSeconds}. <strong>fleetd #489 — the paste-race fix.</strong>
|
||||||
@@ -587,10 +604,19 @@ public final class LeadRollover {
|
|||||||
// also exactly the case that reported false success in the real incident (the
|
// 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
|
// 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.
|
// 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 {} "
|
log.warn("lead-rollover: /clear on {} was never observed as WORKING after {} "
|
||||||
+ "consecutive IDLE/DONE polls ({} of those were nudged) — "
|
+ "consecutive IDLE/DONE polls ({} of those were nudged) — "
|
||||||
+ "releasing rather than wedging the roll (elapsed={}ms)",
|
+ "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);
|
return new ClearSettleResult(true, elapsedMillis, nudges);
|
||||||
}
|
}
|
||||||
try {
|
try {
|
||||||
|
|||||||
@@ -971,6 +971,14 @@ class LeadRolloverTest {
|
|||||||
assertTrue(message.contains("elapsed=4500ms"), "must print the MEASURED elapsed time — "
|
assertTrue(message.contains("elapsed=4500ms"), "must print the MEASURED elapsed time — "
|
||||||
+ "with this fixture's advancing clock, the wait ran 4500ms before releasing: "
|
+ "with this fixture's advancing clock, the wait ran 4500ms before releasing: "
|
||||||
+ message);
|
+ 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 {
|
} finally {
|
||||||
detachLog(events);
|
detachLog(events);
|
||||||
}
|
}
|
||||||
@@ -1000,9 +1008,53 @@ class LeadRolloverTest {
|
|||||||
ILoggingEvent event = lastEventContaining(events, "lead-rollover: rolled");
|
ILoggingEvent event = lastEventContaining(events, "lead-rollover: rolled");
|
||||||
assertEquals(Level.INFO, event.getLevel());
|
assertEquals(Level.INFO, event.getLevel());
|
||||||
String message = event.getFormattedMessage();
|
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 "
|
+ "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<ILoggingEvent> 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 {
|
} finally {
|
||||||
detachLog(events);
|
detachLog(events);
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user