fleet/fleetd
3
0
Fork 0
Code Issues 73 Pull Requests Actions Packages Projects Releases 1 Wiki Activity

LeadRollover's failure logs print the CONFIGURED budget, not the measured wait — the exact thing that hid #489 #494

New Issue
Closed
opened 2026-09-12 04:00:31 +02:00 by ltms · 2 comments
ltms commented 2026-09-12 04:00:31 +02:00
Owner
Copy Link
Copy Source

Found by the fleet01 lead, reviewing #489/#490 read-only. Their framing: "the nudge loop needs a bound and a named failure message, not a happy path … if the pickup never comes, the useful outcome is a failure that says which pane, how many nudges, and how long — not a 20-second budget quietly elapsing the way the 438 ms one quietly did not."

They are right, and the fix in #490 does not close it. #490 made the wait real. It did not make the wait observable.

The three ways the roll can end, and what an operator sees

LeadRollover.java, measured on main at the deployed commit:

Path Line Level What it prints
clear never settles (deadline expiry) :400 warn pane, cfg.clearSettleSeconds(), token
pickup never seen, grace limit hit :569 info pane, poll count, nudge count — then releases and sends bootstrapText anyway
success :406 info lead-rollover: rolled token=… lead=…

Defect 1 — :400 prints a number it did not measure

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

cfg.clearSettleSeconds() is the configured budget. It is not how long the wait ran. An operator reads "within 20s" and concludes the daemon waited 20 seconds.

This is not theoretical. It is the precise shape that hid #489 for a day. The live roll on 2026-09-12 used 438 ms of a 20-second budget and reported success:

00:03:43.560  turn_duration
00:03:43.998  lead-rollover: rolled          <- 438 ms for the whole four-step roll
00:03:44.309  Unknown command: /clearFresh   <- in the LEAD's transcript, not in the daemon log

Had the wait failed instead of passing, this line would have said within 20s while the truth was 0.438s. The log would have been confidently wrong, not merely silent. Same class as the a-status-field-must-read-the-source-the-behaviour-reads lesson: print the value the behaviour actually produced, never the one that configured it.

The elapsed time is already available — nowMillis is injected and the method computes deadline from it. Nothing needs new plumbing.

Defect 2 — the grace-limit release is an info, and it is a success

:569 fires when /clear was never observed as WORKING after 8 consecutive IDLE/DONE polls. It then return true, so runRollover proceeds to send bootstrapText into a pane where /clear may never have run. That is the release-rather-than-wedge trade, and I still think release is right — a wedged lead is worse than a messy one.

But it is logged at info and followed by lead-rollover: rolled. An operator grepping for WARN sees a clean roll. The one case where the roll is most likely to have produced /clearFresh-shaped garbage is the case that reports success most loudly.

Asked for

  1. :400 — log the measured elapsed milliseconds, and the nudge count. Keep the configured budget too, but label both, so the two can be compared. A line that shows configured=20s elapsed=438ms diagnoses #489 on sight.
  2. :569 — raise to warn, add measured elapsed and the target pane. Keep the release behaviour; only make it visible.
  3. :406 — the success line should carry the elapsed time as well. A roll that "succeeds" in 438 ms is the signal, and right now nothing prints it.
  4. A test per changed line that asserts the content of the message, not that a message was emitted. Assert the measured number is present and differs from the configured one where the fixture makes them differ.

What is already proven, so nobody re-does it

I ran two mutations today against the deployed code, with a control after each. Baseline LeadRolloverTest = 29 tests, 0 failures.

  • Restore the original defect (call site back to waitUntilAtTurnBoundary): 1 failure, clearPickupIsNudgedBeforeBootstrapTextWhenPaneStaysIdle. So a test does exist that catches the original bug — the fleet01 lead's first question is answered yes.
  • Reduce the wait to a nudge-once stub (agents.submit(target); return true; — satisfies "a nudge happened, ordered between /clear and bootstrapText" and nothing else): 4 failures + 1 error. So the suite is not merely pinning the nudge; three tests assert bootstrapText is not sent when the wait should not release.
  • Controls after each restore: 29 / 0, source shasum byte-identical to the pristine copy both times.

So #490's behaviour is pinned. Its observability is not pinned at all, and that is what this ticket is for.

Related: #486 (the same loop hangs a suite instead of failing it, because the injected clock never advances while settleSleeper is a no-op — note that fixing this ticket by measuring elapsed time will read that frozen clock, so the tests must set it deliberately), #489, #490, #480.

Found by the fleet01 lead, reviewing #489/#490 read-only. Their framing: *"the nudge loop needs a bound and a named failure message, not a happy path … if the pickup never comes, the useful outcome is a failure that says which pane, how many nudges, and how long — not a 20-second budget quietly elapsing the way the 438 ms one quietly did not."* They are right, and the fix in #490 does not close it. #490 made the wait real. It did not make the wait **observable**. ## The three ways the roll can end, and what an operator sees `LeadRollover.java`, measured on `main` at the deployed commit: | Path | Line | Level | What it prints | |---|---|---|---| | clear never settles (deadline expiry) | `:400` | `warn` | pane, **`cfg.clearSettleSeconds()`**, token | | pickup never seen, grace limit hit | `:569` | `info` | pane, poll count, nudge count — **then releases and sends `bootstrapText` anyway** | | success | `:406` | `info` | `lead-rollover: rolled token=… lead=…` | ## Defect 1 — `:400` prints a number it did not measure ```java 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()); ``` `cfg.clearSettleSeconds()` is the **configured** budget. It is not how long the wait ran. An operator reads "within 20s" and concludes the daemon waited 20 seconds. This is not theoretical. It is the precise shape that hid #489 for a day. The live roll on 2026-09-12 used **438 ms of a 20-second budget** and reported success: ``` 00:03:43.560 turn_duration 00:03:43.998 lead-rollover: rolled <- 438 ms for the whole four-step roll 00:03:44.309 Unknown command: /clearFresh <- in the LEAD's transcript, not in the daemon log ``` Had the wait failed instead of passing, this line would have said `within 20s` while the truth was 0.438s. The log would have been confidently wrong, not merely silent. Same class as the `a-status-field-must-read-the-source-the-behaviour-reads` lesson: **print the value the behaviour actually produced, never the one that configured it.** The elapsed time is already available — `nowMillis` is injected and the method computes `deadline` from it. Nothing needs new plumbing. ## Defect 2 — the grace-limit release is an `info`, and it is a success `:569` fires when `/clear` was never observed as `WORKING` after 8 consecutive `IDLE`/`DONE` polls. It then `return true`, so `runRollover` proceeds to send `bootstrapText` into a pane where `/clear` may never have run. That is the release-rather-than-wedge trade, and I still think release is right — a wedged lead is worse than a messy one. But it is logged at `info` and followed by `lead-rollover: rolled`. An operator grepping for `WARN` sees a clean roll. The one case where the roll is most likely to have produced `/clearFresh`-shaped garbage is the case that reports success most loudly. ## Asked for 1. `:400` — log the **measured** elapsed milliseconds, and the nudge count. Keep the configured budget too, but label both, so the two can be compared. A line that shows `configured=20s elapsed=438ms` diagnoses #489 on sight. 2. `:569` — raise to `warn`, add measured elapsed and the target pane. Keep the release behaviour; only make it visible. 3. `:406` — the success line should carry the elapsed time as well. A roll that "succeeds" in 438 ms is the signal, and right now nothing prints it. 4. A test per changed line that asserts the **content** of the message, not that a message was emitted. Assert the measured number is present and differs from the configured one where the fixture makes them differ. ## What is already proven, so nobody re-does it I ran two mutations today against the deployed code, with a control after each. Baseline `LeadRolloverTest` = 29 tests, 0 failures. - **Restore the original defect** (call site back to `waitUntilAtTurnBoundary`): **1 failure**, `clearPickupIsNudgedBeforeBootstrapTextWhenPaneStaysIdle`. So a test does exist that catches the original bug — the fleet01 lead's first question is answered yes. - **Reduce the wait to a nudge-once stub** (`agents.submit(target); return true;` — satisfies "a nudge happened, ordered between `/clear` and `bootstrapText`" and nothing else): **4 failures + 1 error**. So the suite is not merely pinning the nudge; three tests assert `bootstrapText` is *not* sent when the wait should not release. - Controls after each restore: 29 / 0, source `shasum` byte-identical to the pristine copy both times. So #490's behaviour is pinned. **Its observability is not pinned at all**, and that is what this ticket is for. Related: #486 (the same loop hangs a suite instead of failing it, because the injected clock never advances while `settleSleeper` is a no-op — note that fixing this ticket by measuring elapsed time will read that frozen clock, so the tests must set it deliberately), #489, #490, #480.
ltms commented 2026-09-12 04:09:08 +02:00
Author
Owner
Copy Link
Copy Source

Three corrections and one generalisation, all from the fleet01 lead's second read

1. The release-and-send trade: use this reason, not the one in the ticket

I justified sending bootstrapText after the grace-limit release with "a wedged lead is worse than a messy one". That is a preference, and someone will reopen it. The fleet01 lead supplied the argument that closes it, and it is better:

At that point the code cannot tell "the /clear landed but the pickup went undetected" apart from "the /clear never landed". Those two states need opposite responses, and only one branch is non-fatal in both:

/clear landed /clear never landed
send bootstrapText session saved concatenated mess, lead intact
do not send it lead gone, no bootstrap, no session pane untouched

So releasing and sending is not a taste for mess over wedging. It is the only branch with no fatal cell. This also disposes of the obvious third option — "abort the roll and leave the pane alone" — which is strictly worse, because leaving an already-cleared pane alone is the fatal cell.

Do not change the behaviour. This replaces the reason, not the code.

2. The generalisation. This defect has now appeared three times in three subsystems.

The fleet01 lead names two earlier instances alongside this one:

  • this ticket — LeadRollover:400 prints cfg.clearSettleSeconds() where a reader takes it as the measured wait,
  • their backend-error classification: off line,
  • the heldDurable literal found on #438.

All three are a field that reads as derived but is actually a constant, printed in a channel an operator trusts, wrong in the direction that says everything is fine. Not silent — confidently wrong, which is worse, because a wrong answer terminates the search where a missing one continues it.

Three instances across three subsystems is enough to state the rule:

If a log line or a status field reads as a measurement, it must come from the measurement — never from the thing the measurement was supposed to be checked against. Print both when both matter. elapsed=0.438s budget=20s is right; within 20s is a lie in every case where the line matters at all.

That rule is what this ticket should be reviewed against, and it is broader than the three lines listed above. The "find what else has this shape" instruction in the worker's brief covers the same ground.

3. Correction to the mutation numbers I published

I reported mutation 2 as "4 failures + 1 error". The error should be counted as nothing, and the peer spotted why before I checked.

submitThatThrowsDoesNotAbortTheRoll:629 errored rather than failed. Reading the stack, the exception escaped from my stub, not from an assertion catching the stub:

java.lang.RuntimeException: simulated herdr transport failure on submit
  at LeadRolloverTest$5.call(LeadRolloverTest.java:614)
  at herdr.AgentControl.submit(AgentControl.java:127)
  at lead.LeadRollover.waitForClearPickupAndSettle(LeadRollover.java:550)   <- my stub's bare submit()
  at lead.LeadRollover.runRollover(LeadRollover.java:398)

My stub was agents.submit(target); return true; with no try/catch. The real method wraps that call. So the mutant broke the test; the test did not catch the mutant. That is the mutant removing a try/catch incidentally — a different property from the one mutation 2 was built to probe.

Corrected count: mutation 2 = 4 failures. The conclusion is unchanged and rests entirely on those four, three of which assert the negative (bootstrapText is not sent when the wait should not release). Those are assertions firing, not collateral.

The general rule, worth applying to every future battery: when a mutation produces errors as well as failures, count only the failures. An error can be the mutant breaking the test rather than the test catching the mutant — the same family as an equivalent mutant, where the result looks like signal and is not.

## Three corrections and one generalisation, all from the fleet01 lead's second read ### 1. The release-and-send trade: use this reason, not the one in the ticket I justified sending `bootstrapText` after the grace-limit release with "a wedged lead is worse than a messy one". That is a preference, and someone will reopen it. The fleet01 lead supplied the argument that closes it, and it is better: **At that point the code cannot tell "the `/clear` landed but the pickup went undetected" apart from "the `/clear` never landed".** Those two states need opposite responses, and only one branch is non-fatal in both: | | `/clear` landed | `/clear` never landed | |---|---|---| | **send `bootstrapText`** | session saved | concatenated mess, lead intact | | **do not send it** | **lead gone, no bootstrap, no session** | pane untouched | So releasing and sending is not a taste for mess over wedging. It is the only branch with no fatal cell. This also disposes of the obvious third option — "abort the roll and leave the pane alone" — which is strictly worse, because leaving an already-cleared pane alone *is* the fatal cell. **Do not change the behaviour.** This replaces the reason, not the code. ### 2. The generalisation. This defect has now appeared three times in three subsystems. The fleet01 lead names two earlier instances alongside this one: - this ticket — `LeadRollover:400` prints `cfg.clearSettleSeconds()` where a reader takes it as the measured wait, - their `backend-error classification: off` line, - the `heldDurable` literal found on #438. All three are **a field that reads as derived but is actually a constant, printed in a channel an operator trusts, wrong in the direction that says everything is fine.** Not silent — confidently wrong, which is worse, because a wrong answer terminates the search where a missing one continues it. Three instances across three subsystems is enough to state the rule: > **If a log line or a status field reads as a measurement, it must come from the measurement — never from the thing the measurement was supposed to be checked against.** Print both when both matter. `elapsed=0.438s budget=20s` is right; `within 20s` is a lie in every case where the line matters at all. That rule is what this ticket should be reviewed against, and it is broader than the three lines listed above. The "find what else has this shape" instruction in the worker's brief covers the same ground. ### 3. Correction to the mutation numbers I published I reported mutation 2 as **"4 failures + 1 error"**. The error should be counted as nothing, and the peer spotted why before I checked. `submitThatThrowsDoesNotAbortTheRoll:629` errored rather than failed. Reading the stack, the exception escaped **from my stub**, not from an assertion catching the stub: ``` java.lang.RuntimeException: simulated herdr transport failure on submit at LeadRolloverTest$5.call(LeadRolloverTest.java:614) at herdr.AgentControl.submit(AgentControl.java:127) at lead.LeadRollover.waitForClearPickupAndSettle(LeadRollover.java:550) <- my stub's bare submit() at lead.LeadRollover.runRollover(LeadRollover.java:398) ``` My stub was `agents.submit(target); return true;` with no `try`/`catch`. The real method wraps that call. So the mutant broke the test; the test did not catch the mutant. That is the mutant removing a `try`/`catch` incidentally — a different property from the one mutation 2 was built to probe. **Corrected count: mutation 2 = 4 failures.** The conclusion is unchanged and rests entirely on those four, three of which assert the negative (`bootstrapText` is not sent when the wait should not release). Those are assertions firing, not collateral. The general rule, worth applying to every future battery: **when a mutation produces errors as well as failures, count only the failures.** An error can be the mutant breaking the test rather than the test catching the mutant — the same family as an equivalent mutant, where the result looks like signal and is not.
ltms commented 2026-09-12 04:46:12 +02:00
Author
Owner
Copy Link
Copy Source

Done — PR #496 merged as 8f59019

Three commits: 3fb3311, c87cc25, e966cba.

Verified by me, not taken from the worker's report:

at e966cba (PR head):   mvn clean install -> Tests run: 1681, Failures: 0, BUILD SUCCESS
                        LeadRolloverTest  -> 33/0
                        Gitea CI          -> success
at 8f59019 (the merge): mvn clean install -> Tests run: 1681, Failures: 0, BUILD SUCCESS

Mutation M2 (PICKUP_GRACE_POLLS 8 → 5), run by me in a detached worktree: 2 failures, clearGraceReleaseLogIsWarnWithMeasuredElapsed and successLogPrintsMeasuredElapsedForTheWholeRoll. The line the mutant emitted read after 5 consecutive IDLE/DONE polls (4 of those were nudged), so both numbers now follow the loop rather than the constant. Restored, shasum -a 256 byte-identical, control 33/0 green.

The four log paths this ticket was about

line what it printed before what it prints now
turn-settle timeout within {}s = the configured budget configured={}s elapsed={}ms
/clear-settle timeout within {}s = the configured budget configured={}s elapsed={}ms nudges={}
grace release INFO, poll count and nudges both constants WARN, both counters, plus elapsed={}ms
success no duration at all elapsedMs={} for the whole roll

The /clear-settle timeout line is the one that matters most: nudges there is a genuine measurement that varies with the run, and it is covered by a test that can tell it from a constant.

Two things this ticket did NOT achieve, stated plainly

1. The grace-release line cannot be pinned by any test. idlePollsAwaitingPickup and nudges each have exactly one write site, both on the same branch of the same loop, so no input can make them differ from PICKUP_GRACE_POLLS and PICKUP_GRACE_POLLS - 1. The change there buys one source of truth instead of two — so a later change to the loop cannot leave the message reporting a number the loop no longer produces — and nothing more. That limit is written into the code comment, and the worker reported the equivalent mutant honestly instead of manufacturing a failure count.

2. The first follow-up's test did not pin its own fix, and I only found that by mutating it. c87cc25 added an assertion that built its expected value from LeadRollover.PICKUP_GRACE_POLLS - 1 — the exact expression the fix had just removed from the production code. Reverting the fix left all 33 tests green. A harness-proof cell (breaking the asserted substring) gave 1 failure naming the test, so that zero was real.

The general rule, which is the most reusable thing this ticket produced: a test that derives its expected value the same way the code derives the real one is vacuous. Both sides move together and the assertion proves nothing. e966cba replaces it with plain literals and says in a comment that the literals are deliberate.

Spun out

  • #501 — Injector.java:383-387 prints READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS / 1000 as if it were how long the wait took. That is this ticket's original defect, verbatim, in the delivery loop, on the path that fails queued messages. Found by the worker's same-shape sweep, confirmed by me. It is a worse instance than this one, because nothing there measures wall-clock time at all and the two quantities are not equal by construction.

Closing this. #501 carries the remaining work.

## Done — PR #496 merged as `8f59019` Three commits: `3fb3311`, `c87cc25`, `e966cba`. Verified by me, not taken from the worker's report: ``` at e966cba (PR head): mvn clean install -> Tests run: 1681, Failures: 0, BUILD SUCCESS LeadRolloverTest -> 33/0 Gitea CI -> success at 8f59019 (the merge): mvn clean install -> Tests run: 1681, Failures: 0, BUILD SUCCESS ``` Mutation M2 (`PICKUP_GRACE_POLLS` 8 → 5), run by me in a detached worktree: 2 failures, `clearGraceReleaseLogIsWarnWithMeasuredElapsed` and `successLogPrintsMeasuredElapsedForTheWholeRoll`. The line the mutant emitted read `after 5 consecutive IDLE/DONE polls (4 of those were nudged)`, so both numbers now follow the loop rather than the constant. Restored, `shasum -a 256` byte-identical, control 33/0 green. ## The four log paths this ticket was about | line | what it printed before | what it prints now | |---|---|---| | turn-settle timeout | `within {}s` = the configured budget | `configured={}s elapsed={}ms` | | `/clear`-settle timeout | `within {}s` = the configured budget | `configured={}s elapsed={}ms nudges={}` | | grace release | `INFO`, poll count and nudges both constants | `WARN`, both counters, plus `elapsed={}ms` | | success | no duration at all | `elapsedMs={}` for the whole roll | The `/clear`-settle timeout line is the one that matters most: `nudges` there is a genuine measurement that varies with the run, and it is covered by a test that can tell it from a constant. ## Two things this ticket did NOT achieve, stated plainly **1. The grace-release line cannot be pinned by any test.** `idlePollsAwaitingPickup` and `nudges` each have exactly one write site, both on the same branch of the same loop, so no input can make them differ from `PICKUP_GRACE_POLLS` and `PICKUP_GRACE_POLLS - 1`. The change there buys one source of truth instead of two — so a later change to the loop cannot leave the message reporting a number the loop no longer produces — and nothing more. That limit is written into the code comment, and the worker reported the equivalent mutant honestly instead of manufacturing a failure count. **2. The first follow-up's test did not pin its own fix, and I only found that by mutating it.** `c87cc25` added an assertion that built its expected value from `LeadRollover.PICKUP_GRACE_POLLS - 1` — the exact expression the fix had just removed from the production code. Reverting the fix left all 33 tests green. A harness-proof cell (breaking the asserted substring) gave 1 failure naming the test, so that zero was real. **The general rule, which is the most reusable thing this ticket produced: a test that derives its expected value the same way the code derives the real one is vacuous.** Both sides move together and the assertion proves nothing. `e966cba` replaces it with plain literals and says in a comment that the literals are deliberate. ## Spun out - **#501** — `Injector.java:383-387` prints `READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS / 1000` as if it were how long the wait took. That is this ticket's original defect, verbatim, in the delivery loop, on the path that fails queued messages. Found by the worker's same-shape sweep, confirmed by me. It is a worse instance than this one, because nothing there measures wall-clock time at all and the two quantities are not equal by construction. Closing this. #501 carries the remaining work.
ltms closed this issue 2026-09-12 04:46:18 +02:00
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
Labels
Clear labels
blocked
Cannot start until something else lands. The body says what.
 needs-live-proof
Merged and green, but never shown working on the running daemon. Not the same as done.
 ready-to-delegate
Scope, files and acceptance criteria are written. A worker can be briefed from the body alone.
 silent-default
A feature that compiles, passes tests, and ships turned off. Nine recurrences and counting.
No Label
Milestone
No items
No Milestone
Projects
Clear projects
No project
Assignees
Clear assignees
agent kevin ltms
No Assignees
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#494
Delete Branch "%!s()"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?