fleetd #494: log measured elapsed time, never the configured budget, on a lead-rollover failure/success

- 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.

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;</li>
      *   <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
-     *       choice {@code Injector} makes — and returns {@code true} anyway, logged at {@code info}
-     *       so an operator can see which path ran;</li>
+     *       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;</li>
      *   <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>
      * </ul>
@@ -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) {}
 }

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<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);
+        } 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();
+            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);
+        }
+    }
 }