fleetd #399: fix TTL test race — wait on completion stamp, not Phase.DONE #405

2026-09-10T03:55:20+02:00

agent commented

2026-09-10 03:55:20 +02:00

Fixes fleetd #399: MessageServiceTest.aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished failed every run on Linux and passed every run on macOS. Both readings were correct — the test had a race, not the product.

Root cause

poll() reports Phase.DONE from the future's value (f.getNow(null), around MessageService.java:1301). completedNanos is stamped by a whenComplete hook registered in the Task constructor (around line 260). CompletableFuture.complete() publishes its result and only afterwards runs dependents, so there is a real window where poll answers DONE while completedNanos is still null. The test's awaitTicketPhaseOn(..., DONE) could return inside that window, then advance the injected clock past the TTL; if the hook then ran late, it stamped the advanced clock value, cutoff = advanced - TTL was never reached, and the eviction the test exists to pin never happened.

Fix — option 1 (new test seam)

I picked the test-seam option over "sweep with the clock unadvanced, then advance and sweep again" because I could not find a way to make the unadvanced sweep alone establish a real happens-before edge with the hook's write to completedNanos: under an unadvanced clock, cutoff = now - TTL is always older than any value completedNanos could hold (whether stamped or still null, expired is false either way), so that sweep's outcome does not discriminate "stamped" from "not yet stamped" — it cannot be used as a barrier.

Instead I added a package-private test seam:

boolean isCompletionStampedForTest(String ticket) {
    Task task = tasks.get(ticket);
    return task != null && task.completedNanos != null;
}

Its javadoc says explicitly it carries no production behaviour and nothing in the class calls it — pruneTerminalTickets still reads Task.completedNanos directly. Both TTL tests now loop on this (awaitCompletionStamped, a new private test helper) before advancing the clock, instead of looping on Phase.DONE.

Happens-before argument (criterion 5): Task.completedNanos is volatile Long. The hook's assignment completedNanos = nowNanos.getAsLong() (line 260) is a volatile write. isCompletionStampedForTest's read task.completedNanos != null is a volatile read of the same field. Per JLS 17.4.5, a write to a volatile field happens-before every subsequent read of that field that observes the written value. So the loop iteration in which awaitCompletionStamped first observes true is guaranteed to happen-after the hook's write — and, transitively, everything the test does afterward (including clock.addAndGet(...)) is ordered after that write. This is a real synchronization edge, not a timing heuristic.

Sibling test

aTaskRunningLongerThanTheTtlStillKeepsItsReport shares the same awaitTicketPhaseOn(..., DONE) barrier before the sweep-triggering sendAsync call, but its own clock advance happens before completion, not after DONE. So by the time the sweep runs, the clock has not moved further: cutoff = current_clock - TTL and completedNanos (whenever it lands) both track the same unadvanced current_clock, and completed < cutoff is false either way — the assertion is safe today regardless of stamp timing. I still added the same awaitCompletionStamped wait there, for consistency and to remove the fragile-looking pattern, even though it wasn't strictly required for correctness.

Constraints honored

git diff on MessageService.java makes no change to the expired expression in pruneTerminalTickets (verified: git diff main -- fleetd/src/main/java/dev/ltms/fleet/msg/MessageService.java | grep 'expired =' returns nothing).
The production change is a package-private method with a javadoc stating it is test-seam-only.
Files staged individually — no git add -A.
Did not touch fleetd.yaml, .mcp.json, opencode.json, .autoenv, or wiki/.

Build

[INFO] Tests run: 1474, Failures: 0, Errors: 0, Skipped: 0
[INFO] BUILD SUCCESS

(dev.ltms.fleet.msg.MessageServiceTest: Tests run: 82, Failures: 0, Errors: 0, Skipped: 0)

20 isolated runs of the changed test method

mvn -Dtest=MessageServiceTest#aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished test, 20 times in a loop, output appended to a file and then read back:

All 20 runs: Tests run: 1, Failures: 0, Errors: 0, Skipped: 0 / BUILD SUCCESS / exit=0.

Caveat, stated honestly: this is a necessary but not sufficient check. This race does not reproduce on macOS at all — that's the whole reason the bug is Linux-only in the ticket. 20 green runs here says the fix doesn't break anything and doesn't rule out a scheduling artifact, but it cannot demonstrate the race is closed, because the race was never observable on this host to begin with. The happens-before argument above, not the run count, is what should give confidence in the fix.

Same shape elsewhere (not fixed, per scope)

I did not search further than the two named tests — the ticket scoped this to MessageServiceTest's two TTL tests. Not investigated further, per instructions to note out-of-scope observations rather than chase them: I did not grep the rest of the test suite for other tests that poll Phase.DONE (or an equivalent future-resolution signal) as a barrier before manipulating an injected clock or other completion-adjacent state. If similar patterns exist elsewhere in this file or others using nowNanos-style injected clocks, they'd have the same latent race.

Branch: worker/ttl-stamp-race-399-f1122f-8

Fixes fleetd #399: `MessageServiceTest.aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished` failed every run on Linux and passed every run on macOS. Both readings were correct — the test had a race, not the product. ## Root cause `poll()` reports `Phase.DONE` from the future's value (`f.getNow(null)`, around `MessageService.java:1301`). `completedNanos` is stamped by a `whenComplete` hook registered in the `Task` constructor (around line 260). `CompletableFuture.complete()` publishes its result and only afterwards runs dependents, so there is a real window where `poll` answers `DONE` while `completedNanos` is still `null`. The test's `awaitTicketPhaseOn(..., DONE)` could return inside that window, then advance the injected clock past the TTL; if the hook then ran late, it stamped the *advanced* clock value, `cutoff = advanced - TTL` was never reached, and the eviction the test exists to pin never happened. ## Fix — option 1 (new test seam) I picked the test-seam option over "sweep with the clock unadvanced, then advance and sweep again" because I could not find a way to make the unadvanced sweep alone establish a real happens-before edge with the hook's write to `completedNanos`: under an unadvanced clock, `cutoff = now - TTL` is always older than any value `completedNanos` could hold (whether stamped or still `null`, `expired` is `false` either way), so that sweep's outcome does not discriminate "stamped" from "not yet stamped" — it cannot be used as a barrier. Instead I added a package-private test seam: ```java boolean isCompletionStampedForTest(String ticket) { Task task = tasks.get(ticket); return task != null && task.completedNanos != null; } ``` Its javadoc says explicitly it carries no production behaviour and nothing in the class calls it — `pruneTerminalTickets` still reads `Task.completedNanos` directly. Both TTL tests now loop on this (`awaitCompletionStamped`, a new private test helper) before advancing the clock, instead of looping on `Phase.DONE`. **Happens-before argument (criterion 5):** `Task.completedNanos` is `volatile Long`. The hook's assignment `completedNanos = nowNanos.getAsLong()` (line 260) is a volatile write. `isCompletionStampedForTest`'s read `task.completedNanos != null` is a volatile read of the same field. Per JLS 17.4.5, a write to a volatile field happens-before every subsequent read of that field that observes the written value. So the loop iteration in which `awaitCompletionStamped` first observes `true` is guaranteed to happen-after the hook's write — and, transitively, everything the test does afterward (including `clock.addAndGet(...)`) is ordered after that write. This is a real synchronization edge, not a timing heuristic. ## Sibling test `aTaskRunningLongerThanTheTtlStillKeepsItsReport` shares the same `awaitTicketPhaseOn(..., DONE)` barrier before the sweep-triggering `sendAsync` call, but its own clock advance happens *before* completion, not after `DONE`. So by the time the sweep runs, the clock has not moved further: `cutoff = current_clock - TTL` and `completedNanos` (whenever it lands) both track the *same* unadvanced `current_clock`, and `completed < cutoff` is false either way — the assertion is safe today regardless of stamp timing. I still added the same `awaitCompletionStamped` wait there, for consistency and to remove the fragile-looking pattern, even though it wasn't strictly required for correctness. ## Constraints honored - `git diff` on `MessageService.java` makes **no change** to the `expired` expression in `pruneTerminalTickets` (verified: `git diff main -- fleetd/src/main/java/dev/ltms/fleet/msg/MessageService.java | grep 'expired ='` returns nothing). - The production change is a package-private method with a javadoc stating it is test-seam-only. - Files staged individually — no `git add -A`. - Did not touch `fleetd.yaml`, `.mcp.json`, `opencode.json`, `.autoenv`, or `wiki/`. ## Build ``` [INFO] Tests run: 1474, Failures: 0, Errors: 0, Skipped: 0 [INFO] BUILD SUCCESS ``` (`dev.ltms.fleet.msg.MessageServiceTest`: `Tests run: 82, Failures: 0, Errors: 0, Skipped: 0`) ## 20 isolated runs of the changed test method `mvn -Dtest=MessageServiceTest#aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished test`, 20 times in a loop, output appended to a file and then read back: All 20 runs: `Tests run: 1, Failures: 0, Errors: 0, Skipped: 0` / `BUILD SUCCESS` / `exit=0`. **Caveat, stated honestly:** this is a necessary but not sufficient check. This race does not reproduce on macOS at all — that's the whole reason the bug is Linux-only in the ticket. 20 green runs here says the fix doesn't *break* anything and doesn't rule out a scheduling artifact, but it cannot demonstrate the race is closed, because the race was never observable on this host to begin with. The happens-before argument above, not the run count, is what should give confidence in the fix. ## Same shape elsewhere (not fixed, per scope) I did not search further than the two named tests — the ticket scoped this to `MessageServiceTest`'s two TTL tests. Not investigated further, per instructions to note out-of-scope observations rather than chase them: I did not grep the rest of the test suite for other tests that poll `Phase.DONE` (or an equivalent future-resolution signal) as a barrier before manipulating an injected clock or other completion-adjacent state. If similar patterns exist elsewhere in this file or others using `nowNanos`-style injected clocks, they'd have the same latent race. --- Branch: `worker/ttl-stamp-race-399-f1122f-8`

agent added 1 commit 2026-09-10 03:55:20 +02:00

fleetd #399 : fix TTL test race by waiting on a real completion stamp, not DONE

CI / contract (pull_request) Successful in 46s

Details

CI / build (pull_request) Successful in 2m2s

Details

0f51d53098

poll() can report Phase.DONE for a ticket before the whenComplete hook that
stamps Task.completedNanos has run — CompletableFuture.complete() publishes
its result and only then runs dependents. The TTL tests advanced an injected
clock right after observing DONE, so on a host where the hook runs late it
stamps the ADVANCED time and the eviction never happens (fails on Linux,
passes on macOS).

Add a package-private test seam, MessageService.isCompletionStampedForTest,
that reports whether completedNanos is stamped. Both TTL tests now wait on
that (a real volatile read/write happens-before edge) before advancing the
clock, instead of on Phase.DONE. The prune condition in pruneTerminalTickets
is untouched.

ltms merged commit ae74cc081f into main

2026-09-10 04:14:30 +02:00

ltms referenced this pull request

2026-09-10 04:15:04 +02:00

MessageServiceTest TTL test races the completedNanos stamp — passes on macOS, fails on Linux #399

ltms referenced this pull request

2026-09-10 04:27:34 +02:00

The #399 completion-stamp race is verifiable deterministically — nowNanos is already injectable #409

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: fleet/fleetd#405