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

Injector's readiness-grace warn prints the configured budget as if it were elapsed time — #494's defect, in the delivery loop #501

New Issue
Closed
opened 2026-09-12 04:44:37 +02:00 by ltms · 1 comment
ltms commented 2026-09-12 04:44:37 +02:00
Owner
Copy Link
Copy Source

Found by the worker on PR #496 while sweeping for the same shape as fleetd #494, and confirmed by me in the tree. Not fixed there — it is a different file and a different loop, so it gets its own ticket.

The line

fleetd/src/main/java/dev/ltms/fleet/inject/Injector.java:383-387:

log.warn("readiness grace for {} expired after {} polls ({}s): target never "
        + "became deliverable, so failing {} queued message(s) that never "
        + "reached its pane",
        target, READINESS_GRACE_POLLS,
        READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS / 1000, notReady.size());

Both numbers an operator would read as measurements are constants.

Two separate defects, and the second one is the serious one

1. The poll count is the constant, not the counter

READINESS_GRACE_POLLS (:81, value 240) is printed where the loop's own counter t.notReadySincePoll is in scope. It is incremented at :373 and reset at :304, :355 and :389. On this branch it has just reached the threshold, so the two agree by construction — the same equivalent-mutant situation as the line fixed in #494, and the fix there is the same: print the counter, so the message gets one source of truth instead of two.

Low severity on its own.

2. ({}s) is arithmetic on two constants, presented as how long the wait took

READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS / 1000

This is #494's original defect, verbatim: a field that reads as a measurement and is a constant, in a channel an operator trusts, wrong in the direction that says everything is normal. Nothing here measures wall-clock time at all.

It is not merely equivalent-by-construction, and that is what separates it from defect 1:

  • t.notReadySincePoll counts consecutive non-ready samples, and it increments only when p != null (:373). Polls that do not meet that condition advance the clock without advancing the counter.
  • The poll loop's real period is not guaranteed to be POLL_INTERVAL_MILLIS. Under load, or after the host sleeps, the wall-clock gap between the first non-ready sample and this line can be much larger than 240 * POLL_INTERVAL_MILLIS.
  • Separately: nanoTime stops while this Mac is asleep (see the note in the daemon's timing code), so any derived-from-constants duration is doubly untrustworthy here.

So an operator reading "expired after 240 polls (Ns)" is told a number that was never measured, on the path where queued messages are being failed — exactly the moment they need to know how long the target really had.

Why this matters more than #494's instance

#494's line fires during a lead rollover, which is rare and operator-initiated. This one fires in the delivery loop, on the path that marks queued messages NOT_DELIVERED and releases the target (CB-114). It is the line an operator reaches for when a member never picked up its brief, and it currently answers with the configuration rather than with what happened.

Asked for

  1. Measure the elapsed time from the first non-ready sample to this line, using the same injected-clock approach LeadRollover now uses, and print it as elapsed=...ms next to the configured budget, both labelled. Never print a duration derived only from constants.
  2. Print t.notReadySincePoll instead of READINESS_GRACE_POLLS for the poll count.
  3. Tests: assert on plain literal expected values. Do not build the expectation out of READINESS_GRACE_POLLS or POLL_INTERVAL_MILLIS — a test that derives its expectation the way the code does cannot see a change to either. That exact mistake was caught on PR #496 and is what made its first follow-up ineffective.
  4. State honestly in the code comment which of the two numbers a test can actually discriminate. Item 2 is equal-by-construction on this branch; item 1 is not, and item 1 is the one that needs a real test.

Related

  • fleetd #494 — the same shape in LeadRollover, merged in PR #496. Read that PR's comments before starting: it contains the mutation discipline this ticket needs and one worked example of a test that looked like it pinned the fix and did not.
  • fleetd #497 — the inverse family (a sentinel conflating "no" with "cannot tell"). This ticket is not that one; here the vocabulary is fine and the value is simply not measured.
Found by the worker on PR #496 while sweeping for the same shape as fleetd #494, and confirmed by me in the tree. **Not fixed there** — it is a different file and a different loop, so it gets its own ticket. ## The line `fleetd/src/main/java/dev/ltms/fleet/inject/Injector.java:383-387`: ```java log.warn("readiness grace for {} expired after {} polls ({}s): target never " + "became deliverable, so failing {} queued message(s) that never " + "reached its pane", target, READINESS_GRACE_POLLS, READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS / 1000, notReady.size()); ``` Both numbers an operator would read as measurements are constants. ## Two separate defects, and the second one is the serious one ### 1. The poll count is the constant, not the counter `READINESS_GRACE_POLLS` (`:81`, value 240) is printed where the loop's own counter `t.notReadySincePoll` is in scope. It is incremented at `:373` and reset at `:304`, `:355` and `:389`. On this branch it has just reached the threshold, so the two agree by construction — the same equivalent-mutant situation as the line fixed in #494, and the fix there is the same: print the counter, so the message gets one source of truth instead of two. Low severity on its own. ### 2. `({}s)` is arithmetic on two constants, presented as how long the wait took ```java READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS / 1000 ``` This is **#494's original defect, verbatim**: a field that reads as a measurement and is a constant, in a channel an operator trusts, wrong in the direction that says everything is normal. Nothing here measures wall-clock time at all. It is not merely equivalent-by-construction, and that is what separates it from defect 1: - `t.notReadySincePoll` counts **consecutive non-ready samples**, and it increments only when `p != null` (`:373`). Polls that do not meet that condition advance the clock without advancing the counter. - The poll loop's real period is not guaranteed to be `POLL_INTERVAL_MILLIS`. Under load, or after the host sleeps, the wall-clock gap between the first non-ready sample and this line can be much larger than `240 * POLL_INTERVAL_MILLIS`. - Separately: `nanoTime` stops while this Mac is asleep (see the note in the daemon's timing code), so any derived-from-constants duration is doubly untrustworthy here. So an operator reading "expired after 240 polls (Ns)" is told a number that was never measured, on the path where queued messages are being **failed** — exactly the moment they need to know how long the target really had. ## Why this matters more than #494's instance #494's line fires during a lead rollover, which is rare and operator-initiated. This one fires in the delivery loop, on the path that marks queued messages `NOT_DELIVERED` and releases the target (CB-114). It is the line an operator reaches for when a member never picked up its brief, and it currently answers with the configuration rather than with what happened. ## Asked for 1. Measure the elapsed time from the first non-ready sample to this line, using the same injected-clock approach `LeadRollover` now uses, and print it as `elapsed=...ms` **next to** the configured budget, both labelled. Never print a duration derived only from constants. 2. Print `t.notReadySincePoll` instead of `READINESS_GRACE_POLLS` for the poll count. 3. Tests: assert on **plain literal** expected values. Do not build the expectation out of `READINESS_GRACE_POLLS` or `POLL_INTERVAL_MILLIS` — a test that derives its expectation the way the code does cannot see a change to either. That exact mistake was caught on PR #496 and is what made its first follow-up ineffective. 4. State honestly in the code comment which of the two numbers a test can actually discriminate. Item 2 is equal-by-construction on this branch; item 1 is not, and item 1 is the one that needs a real test. ## Related - fleetd #494 — the same shape in `LeadRollover`, merged in PR #496. Read that PR's comments before starting: it contains the mutation discipline this ticket needs and one worked example of a test that looked like it pinned the fix and did not. - fleetd #497 — the inverse family (a sentinel conflating "no" with "cannot tell"). This ticket is **not** that one; here the vocabulary is fine and the value is simply not measured.
ltms commented 2026-09-12 05:11:19 +02:00
Author
Owner
Copy Link
Copy Source

Fixed and merged in PR #503, merge commit 136312f on main.

What changed. Injector now stamps System.currentTimeMillis() on the first poll where a target
is not deliverable, and the readiness-grace warn prints the real time between that stamp and grace
expiry. Before, the line computed READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS — a constant
dressed up as a measurement. Any pause in the poll loop (a slow herdr call, a sleeping Mac) made the
printed time wrong, and an operator reading it had no way to tell.

The clock is injected as a LongSupplier, so the test can drive it.

What I measured myself, at merge time:

  • Trial merge onto main built before merging, because a clean auto-merge is not a compiling merge:
    Tests run: 1689, Failures: 0, Errors: 0, Skipped: 0, BUILD SUCCESS. InjectorTest 34/0.
  • Gitea CI on ac351ee: success.
  • My own mutation, on the half the worker did not change — the stamp site. I made the first-
    sample guard restamp the clock on every non-ready poll. Two greps with different search strings
    proved the mutant applied. Result: Tests run: 34, Failures: 1, failing at
    InjectorTest.readinessGraceExpiryLogsTheMeasuredElapsedTimeNotArithmeticOnConstants, on the
    clock-read counter ("the readiness-not-ready branch should read the clock exactly twice"). Restored,
    shasum -a 256 byte-identical, control run 34/0 green.

Two notes, neither a blocker.

The poll-count half of the log line is an equivalent mutant: t.notReadySincePoll and
READINESS_GRACE_POLLS are equal by construction at the point the warn fires, because the counter
has exactly one write site on that branch. No test can tell the two apart. The worker said so
instead of reporting a kill it did not get, and the code comment states the limit. That is the right
outcome — the fix buys one source of truth, not proven coverage.

The clock reaches Injector through a package-private constructor overload, while the public
constructors default it to System::currentTimeMillis. My brief asked for that shape. fleetd #415's
antidote — a required parameter with no defaulted overload — would have been just as cheap here,
and would match LeadRollover and the new Fleetd.awaitHerdr. I accepted it because the
silent-survivor risk #415 names is not present: the field is final and both public constructors
delegate to the overload, so a future constructor cannot compile without supplying a clock. There is
also exactly one production construction site (Fleetd.java:531). Recording the choice so the next
reader does not take it for an oversight.

Closing.

Fixed and merged in PR #503, merge commit `136312f` on `main`. **What changed.** `Injector` now stamps `System.currentTimeMillis()` on the first poll where a target is not deliverable, and the readiness-grace warn prints the real time between that stamp and grace expiry. Before, the line computed `READINESS_GRACE_POLLS * POLL_INTERVAL_MILLIS` — a constant dressed up as a measurement. Any pause in the poll loop (a slow herdr call, a sleeping Mac) made the printed time wrong, and an operator reading it had no way to tell. The clock is injected as a `LongSupplier`, so the test can drive it. **What I measured myself, at merge time:** - Trial merge onto `main` built before merging, because a clean auto-merge is not a compiling merge: `Tests run: 1689, Failures: 0, Errors: 0, Skipped: 0`, BUILD SUCCESS. `InjectorTest` 34/0. - Gitea CI on `ac351ee`: success. - My own mutation, on the half the worker did not change — the **stamp site**. I made the first- sample guard restamp the clock on every non-ready poll. Two greps with different search strings proved the mutant applied. Result: `Tests run: 34, Failures: 1`, failing at `InjectorTest.readinessGraceExpiryLogsTheMeasuredElapsedTimeNotArithmeticOnConstants`, on the clock-read counter ("the readiness-not-ready branch should read the clock exactly twice"). Restored, `shasum -a 256` byte-identical, control run 34/0 green. **Two notes, neither a blocker.** The poll-count half of the log line is an **equivalent mutant**: `t.notReadySincePoll` and `READINESS_GRACE_POLLS` are equal by construction at the point the warn fires, because the counter has exactly one write site on that branch. No test can tell the two apart. The worker said so instead of reporting a kill it did not get, and the code comment states the limit. That is the right outcome — the fix buys one source of truth, not proven coverage. The clock reaches `Injector` through a package-private constructor overload, while the public constructors default it to `System::currentTimeMillis`. My brief asked for that shape. fleetd #415's antidote — a **required** parameter with no defaulted overload — would have been just as cheap here, and would match `LeadRollover` and the new `Fleetd.awaitHerdr`. I accepted it because the silent-survivor risk #415 names is not present: the field is `final` and both public constructors delegate to the overload, so a future constructor cannot compile without supplying a clock. There is also exactly one production construction site (`Fleetd.java:531`). Recording the choice so the next reader does not take it for an oversight. Closing.
ltms closed this issue 2026-09-12 05:11:24 +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#501
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?