Merge #496: lead-rollover logs measured elapsed time and measured counts, never the configured budget (fleetd #494)
Three commits. All verified by the lead in a detached worktree, not taken from the worker's report.3fb3311— the /clear-settle and success paths return measured elapsed time and a real nudge countc87cc25— print the measured nudge count; fix the same defect on the sibling turn-settle timeout linee966cba— the poll count on the same line was still a constant; the test could not tell the difference Lead verification ate966cba: mvn clean install -> Tests run: 1681, Failures: 0, Errors: 0, Skipped: 0, BUILD SUCCESS LeadRolloverTest -> Tests run: 33, Failures: 0, Errors: 0, Skipped: 0 Gitea CI one966cba: success Mutation M2 (PICKUP_GRACE_POLLS 8 -> 5), run by the lead: 2 failures, clearGraceReleaseLogIsWarnWithMeasuredElapsed and successLogPrintsMeasuredElapsedForTheWholeRoll. The emitted line under the mutant read "after 5 consecutive IDLE/DONE polls (4 of those were nudged)", so both numbers now follow the loop. Restored, shasum byte-identical, control 33/0 green. Known and deliberate limit, stated in the code comment: on the grace-release branch both counters equal the constants by construction (one write site each), so no test can prove the difference on that line. The change buys one source of truth, not provable coverage. The place nudges genuinely varies with the run is the /clear-timeout warn, which is covered by a discriminating test.
This commit was merged in pull request #496.
This commit is contained in:
@@ -381,13 +381,18 @@ 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();
|
||||||
boolean turnSettled = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds());
|
long rollStartMillis = nowMillis.getAsLong();
|
||||||
if (!turnSettled) {
|
TurnSettleResult turnResult = waitUntilAtTurnBoundary(lead, cfg.turnSettleSeconds());
|
||||||
log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) within {}s "
|
if (!turnResult.settled()) {
|
||||||
+ "after confirm() — refusing to send /clear at all; the calling lead's "
|
// fleetd #494 follow-up: this line had the SAME defect as the /clear-timeout line below
|
||||||
+ "own turn is still live and clearing it now would destroy live context "
|
// — cfg.turnSettleSeconds() is the CONFIGURED budget, not how long this wait actually
|
||||||
+ "(token={})",
|
// ran. Print the measured elapsed time alongside it, labelled, exactly like the /clear
|
||||||
lead, cfg.turnSettleSeconds(), p.token());
|
// 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;
|
return;
|
||||||
}
|
}
|
||||||
|
|
||||||
@@ -395,15 +400,22 @@ public final class LeadRollover {
|
|||||||
// /clear is housekeeping, not a delegated turn, and routing it through Injector wedges the
|
// /clear is housekeeping, not a delegated turn, and routing it through Injector wedges the
|
||||||
// pane forever (see this class's javadoc).
|
// pane forever (see this class's javadoc).
|
||||||
agents.send(lead, "/clear");
|
agents.send(lead, "/clear");
|
||||||
boolean clearSettled = waitForClearPickupAndSettle(lead, cfg.clearSettleSeconds());
|
ClearSettleResult clearResult = waitForClearPickupAndSettle(lead, cfg.clearSettleSeconds());
|
||||||
if (!clearSettled) {
|
if (!clearResult.settled()) {
|
||||||
log.warn("lead-rollover: pane {} did not reach a turn boundary (IDLE or DONE) within {}s "
|
// fleetd #494: cfg.clearSettleSeconds() is the CONFIGURED budget, not how long the wait
|
||||||
+ "after /clear — NOT sending bootstrapText (token={})",
|
// actually ran — an operator reading only that number wrongly believes it is a measured
|
||||||
lead, cfg.clearSettleSeconds(), p.token());
|
// 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;
|
return;
|
||||||
}
|
}
|
||||||
agents.send(lead, cfg.bootstrapTextFor(p.handoverPath()));
|
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} */
|
/** 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
|
* 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 {
|
||||||
@@ -488,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>
|
||||||
@@ -524,8 +549,9 @@ public final class LeadRollover {
|
|||||||
* Claude Code prompt is a no-op, so repeating it is safe;</li>
|
* Claude Code prompt is a no-op, so repeating it is safe;</li>
|
||||||
* <li>the {@code PICKUP_GRACE_POLLS}th consecutive such poll, with {@code WORKING} still never
|
* <li>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
|
* 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}
|
* choice {@code Injector} makes — and returns {@code settled() == true} anyway, logged at
|
||||||
* so an operator can see which path ran;</li>
|
* {@code warn} with the measured elapsed time (fleetd #494) so an operator can see which
|
||||||
|
* path ran and how long it actually took;</li>
|
||||||
* <li>once {@code WORKING} has been observed, nudging stops and this instead waits for a real
|
* <li>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}.</li>
|
* {@code working → IDLE/DONE} completion boundary before returning {@code true}.</li>
|
||||||
* </ul>
|
* </ul>
|
||||||
@@ -541,15 +567,20 @@ public final class LeadRollover {
|
|||||||
* swallowed and logged at {@code debug}, exactly like {@code Injector.java:437-442} — a failed
|
* swallowed and logged at {@code debug}, exactly like {@code Injector.java:437-442} — a failed
|
||||||
* nudge must not abort the roll.
|
* nudge must not abort the roll.
|
||||||
*
|
*
|
||||||
* @return {@code true} once {@code /clear} has settled, or once the nudge budget was exhausted
|
* @return a {@link ClearSettleResult} whose {@code settled()} is {@code true} once {@code
|
||||||
* with no pickup ever observed (released rather than wedged); {@code false} if {@code
|
* /clear} has settled, or once the nudge budget was exhausted with no pickup ever
|
||||||
* settleSeconds} elapses first — the caller must NOT send {@code bootstrapText} in that
|
* observed (released rather than wedged); {@code false} if {@code settleSeconds} elapses
|
||||||
* case, exactly as before this fix
|
* 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) {
|
private ClearSettleResult waitForClearPickupAndSettle(String target, int settleSeconds) {
|
||||||
long deadline = nowMillis.getAsLong() + TimeUnit.SECONDS.toMillis(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
|
boolean pickedUp = false; // a WORKING sample has been observed since /clear was sent
|
||||||
int idlePollsAwaitingPickup = 0;
|
int idlePollsAwaitingPickup = 0;
|
||||||
|
int nudges = 0;
|
||||||
while (nowMillis.getAsLong() < deadline) {
|
while (nowMillis.getAsLong() < deadline) {
|
||||||
AgentStatus status;
|
AgentStatus status;
|
||||||
try {
|
try {
|
||||||
@@ -563,26 +594,56 @@ public final class LeadRollover {
|
|||||||
pickedUp = true;
|
pickedUp = true;
|
||||||
} else if (status == AgentStatus.IDLE || status == AgentStatus.DONE) {
|
} else if (status == AgentStatus.IDLE || status == AgentStatus.DONE) {
|
||||||
if (pickedUp) {
|
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) {
|
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) — "
|
+ "consecutive IDLE/DONE polls ({} of those were nudged) — "
|
||||||
+ "releasing rather than wedging the roll",
|
+ "releasing rather than wedging the roll (elapsed={}ms)",
|
||||||
target, PICKUP_GRACE_POLLS, PICKUP_GRACE_POLLS - 1);
|
target, idlePollsAwaitingPickup, nudges, elapsedMillis);
|
||||||
return true;
|
return new ClearSettleResult(true, elapsedMillis, nudges);
|
||||||
}
|
}
|
||||||
try {
|
try {
|
||||||
agents.submit(target); // nudge a raced Enter (CB-113) so /clear actually submits
|
agents.submit(target); // nudge a raced Enter (CB-113) so /clear actually submits
|
||||||
} catch (RuntimeException e) {
|
} catch (RuntimeException e) {
|
||||||
log.debug("lead-rollover: resubmit to {} failed (will retry next poll): {}",
|
log.debug("lead-rollover: resubmit to {} failed (will retry next poll): {}",
|
||||||
target, e.getMessage());
|
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
|
// AgentStatus.BLOCKED or UNKNOWN (or an unreadable status, above): neither a pickup
|
||||||
// signal nor a boundary — keep polling without nudging or releasing.
|
// signal nor a boundary — keep polling without nudging or releasing.
|
||||||
settleSleeper.run();
|
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) {}
|
||||||
}
|
}
|
||||||
|
|||||||
@@ -1,5 +1,9 @@
|
|||||||
package dev.ltms.fleet.lead;
|
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 com.fasterxml.jackson.databind.JsonNode;
|
||||||
import dev.ltms.fleet.config.FleetConfig;
|
import dev.ltms.fleet.config.FleetConfig;
|
||||||
import dev.ltms.fleet.herdr.AgentControl;
|
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.DisplayName;
|
||||||
import org.junit.jupiter.api.Test;
|
import org.junit.jupiter.api.Test;
|
||||||
import org.junit.jupiter.api.io.TempDir;
|
import org.junit.jupiter.api.io.TempDir;
|
||||||
|
import org.slf4j.LoggerFactory;
|
||||||
|
|
||||||
import java.io.IOException;
|
import java.io.IOException;
|
||||||
import java.nio.file.Files;
|
import java.nio.file.Files;
|
||||||
@@ -854,4 +859,207 @@ class LeadRolloverTest {
|
|||||||
assertFalse(bootstrapSent.contains("\"handover.md\""),
|
assertFalse(bootstrapSent.contains("\"handover.md\""),
|
||||||
"must not name the raw relative configured value in the text actually sent");
|
"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<ILoggingEvent> attachLog() {
|
||||||
|
Logger logger = (Logger) LoggerFactory.getLogger(LeadRollover.class);
|
||||||
|
logger.setLevel(Level.DEBUG);
|
||||||
|
ListAppender<ILoggingEvent> appender = new ListAppender<>();
|
||||||
|
appender.start();
|
||||||
|
logger.addAppender(appender);
|
||||||
|
return appender;
|
||||||
|
}
|
||||||
|
|
||||||
|
private static void detachLog(ListAppender<ILoggingEvent> appender) {
|
||||||
|
((Logger) LoggerFactory.getLogger(LeadRollover.class)).detachAppender(appender);
|
||||||
|
}
|
||||||
|
|
||||||
|
private static ILoggingEvent lastEventContaining(ListAppender<ILoggingEvent> 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<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 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<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(), "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<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(), "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<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 {
|
||||||
|
detachLog(events);
|
||||||
|
}
|
||||||
|
}
|
||||||
}
|
}
|
||||||
|
|||||||
Reference in New Issue
Block a user