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

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

New Issue
Closed
opened 2026-09-10 03:15:02 +02:00 by ltms · 6 comments
ltms commented 2026-09-10 03:15:02 +02:00
Owner
Copy Link
Copy Source

MessageServiceTest.aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished is not reliable. The fleet01 lead sees it fail every run, in isolation, at 799014e. I see it pass on macOS at the same commit. Both readings are correct — the test has a race.

It is a test defect, not a product regression

Measured on this Mac at 799014e (git rev-parse HEAD = 799014e99dd02a520eb66f655376ed90d5abd070):

full suite:            Tests run: 1469, Failures: 0  BUILD SUCCESS
that method alone, 12x: run 1..12 rc=0, Tests run: 1, Failures: 0   (12 of 12 green)

Reported on fleet01: 1470 run, 1 failure, and the same failure with the method run in isolation at 799014e with no local changes.

The mechanism

Two facts in MessageService.java:

  • poll reports Phase.DONE from the future's value — r = f.getNow(null) then return new TaskView(ticket, Phase.DONE, ...) (:1308).
  • completedNanos is stamped by a dependent action: future.whenComplete((reply, ex) -> completedNanos = nowNanos.getAsLong()), registered in the Task constructor (:260).

CompletableFuture.complete() publishes the result and then fires dependents. So there is a real window where poll answers DONE and completedNanos is still null. pruneTerminalTickets already documents that window at :1348:

A task whose future is done but whose completedNanos is not stamped yet is left alone. That window is the few instructions between complete() and the constructor's whenComplete hook running; the next sweep collects it.

The test's awaitTicketPhaseOn(..., DONE) can return inside that window. Then:

  1. clock.addAndGet(TICKET_TTL_NANOS + 1s) — the injected clock jumps.
  2. The hook runs late and stamps completedNanos with the advanced value.
  3. sendAsync sweeps: cutoff = advanced - TTL, and advanced < advanced - TTL is false, so nothing is evicted.
  4. assertNull(poll(done)) fails with the ticket still present.

That is exactly the reported failure text, including reply=quick result.

Once the race is lost the failure is permanent for that run, because the test performs only one sweep. In production sweeps recur, so a late stamp costs one sweep and the next one collects it — which is why this is a test-only defect.

An injected clock removes wall-clock flake, not schedule flake

Worth writing down, because it is the inference that made this look deterministic. The clock here is a deterministic AtomicLong. The thread interleaving is not. Deterministic inputs do not make a concurrent test deterministic when the assertion depends on a happens-before edge the test never establishes.

Fix direction

The test must not advance the clock until the stamp has actually happened. Awaiting Phase.DONE is the wrong barrier, because DONE is published before the stamp. Options, in the order I would try them:

  1. Expose a package-private test seam that reports whether completedNanos is stamped for a ticket, and await that instead of DONE.
  2. Await the stamp indirectly: sweep once with the clock unadvanced, which proves the hook has run, then advance and sweep again.

Do not "fix" it by widening the prune to treat future.isDone() && completedNanos == null as expired — that would delete a report in the very window the current code deliberately protects, which is what #197 fixed.

The sibling test aTaskRunningLongerThanTheTtlStillKeepsItsReport shares the barrier and should be checked for the same hole, even though its assertion happens to survive a late stamp.

`MessageServiceTest.aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished` is not reliable. The fleet01 lead sees it fail every run, in isolation, at `799014e`. I see it pass on macOS at the same commit. Both readings are correct — the test has a race. ## It is a test defect, not a product regression Measured on this Mac at `799014e` (`git rev-parse HEAD` = `799014e99dd02a520eb66f655376ed90d5abd070`): ``` full suite: Tests run: 1469, Failures: 0 BUILD SUCCESS that method alone, 12x: run 1..12 rc=0, Tests run: 1, Failures: 0 (12 of 12 green) ``` Reported on fleet01: `1470 run, 1 failure`, and the same failure with the method run in isolation at `799014e` with no local changes. ## The mechanism Two facts in `MessageService.java`: - `poll` reports `Phase.DONE` from the future's **value** — `r = f.getNow(null)` then `return new TaskView(ticket, Phase.DONE, ...)` (`:1308`). - `completedNanos` is stamped by a **dependent action**: `future.whenComplete((reply, ex) -> completedNanos = nowNanos.getAsLong())`, registered in the `Task` constructor (`:260`). `CompletableFuture.complete()` publishes the result and *then* fires dependents. So there is a real window where `poll` answers `DONE` and `completedNanos` is still `null`. `pruneTerminalTickets` already documents that window at `:1348`: > A task whose future is done but whose `completedNanos` is not stamped yet is left alone. That window is the few instructions between `complete()` and the constructor's `whenComplete` hook running; the next sweep collects it. The test's `awaitTicketPhaseOn(..., DONE)` can return inside that window. Then: 1. `clock.addAndGet(TICKET_TTL_NANOS + 1s)` — the injected clock jumps. 2. The hook runs late and stamps `completedNanos` with the **advanced** value. 3. `sendAsync` sweeps: `cutoff = advanced - TTL`, and `advanced < advanced - TTL` is false, so nothing is evicted. 4. `assertNull(poll(done))` fails with the ticket still present. That is exactly the reported failure text, including `reply=quick result`. Once the race is lost the failure is permanent for that run, because the test performs only one sweep. In production sweeps recur, so a late stamp costs one sweep and the next one collects it — which is why this is a test-only defect. ## An injected clock removes wall-clock flake, not schedule flake Worth writing down, because it is the inference that made this look deterministic. The clock here is a deterministic `AtomicLong`. The *thread interleaving* is not. Deterministic inputs do not make a concurrent test deterministic when the assertion depends on a happens-before edge the test never establishes. ## Fix direction The test must not advance the clock until the stamp has actually happened. Awaiting `Phase.DONE` is the wrong barrier, because `DONE` is published before the stamp. Options, in the order I would try them: 1. Expose a package-private test seam that reports whether `completedNanos` is stamped for a ticket, and await that instead of `DONE`. 2. Await the stamp indirectly: sweep once with the clock **unadvanced**, which proves the hook has run, then advance and sweep again. Do not "fix" it by widening the prune to treat `future.isDone() && completedNanos == null` as expired — that would delete a report in the very window the current code deliberately protects, which is what #197 fixed. The sibling test `aTaskRunningLongerThanTheTtlStillKeepsItsReport` shares the barrier and should be checked for the same hole, even though its assertion happens to survive a late stamp.
ltms commented 2026-09-10 03:25:49 +02:00
Author
Owner
Copy Link
Copy Source

Third and fourth hosts measured. The race is real, and it is lost reliably only on fleet01 — because that host is nearly saturated.

CI passes at the same commit

Gitea Actions, which runs on Linux:

run 1609  push  main       799014e  -> success     <- the commit both leads tested
run 1610  PR    #396 head  0d07a0f  -> success     <- the branch that reported the failure

So "Linux" is not the variable. Two Linux runs and one macOS host pass; one Linux host fails every time.

fleet01 is at 92% CPU

Measured over ssh just now:

nproc                8
/proc/loadavg        7.37 6.27 5.42        <- sustained, and rising
free -m              11959 total, 424 free, 4583 available

Load 7.37 on 8 cores, and the 1/5/15-minute averages rise rather than fall, so this is sustained rather than a spike. Three opencode processes account for it:

%CPU   RSS(kB)  COMM
 189   850200   opencode
 140   794292   opencode
 115   751996   opencode

About 4.4 cores and 2.4 GB between them.

Why that makes the failure deterministic there

The race is between complete() publishing the result and the constructor's whenComplete dependent action running. On an idle host the dependent action runs almost immediately, so the test's clock advance lands after the stamp and the assertion holds. On a host with every core contended, the thread carrying the dependent action waits to be scheduled, the clock advance wins every time, and the ticket is stamped with the advanced value.

This does not weaken the diagnosis — it completes it. It also explains why the test has been green in CI since #197 landed: CI has never been the loaded case.

Two things worth keeping

  1. A saturated host is a better concurrency-test instrument than an idle one. fleet01 found this because it is busy. When a concurrency test needs proving, run it there, not here.
  2. "Passes in CI" is not evidence that a concurrency test is sound. It is evidence about the load on the runner. Same shape as the reason this bug survived: everyone measured the case where the race is easy to win.

The fix in the issue body is unchanged — the test must await the stamp rather than Phase.DONE. Nothing about the load changes what is wrong with it; the load only decides who notices.

Third and fourth hosts measured. The race is real, and it is lost reliably only on fleet01 — because that host is nearly saturated. ## CI passes at the same commit Gitea Actions, which runs on Linux: ``` run 1609 push main 799014e -> success <- the commit both leads tested run 1610 PR #396 head 0d07a0f -> success <- the branch that reported the failure ``` So "Linux" is not the variable. Two Linux runs and one macOS host pass; one Linux host fails every time. ## fleet01 is at 92% CPU Measured over ssh just now: ``` nproc 8 /proc/loadavg 7.37 6.27 5.42 <- sustained, and rising free -m 11959 total, 424 free, 4583 available ``` Load 7.37 on 8 cores, and the 1/5/15-minute averages rise rather than fall, so this is sustained rather than a spike. Three `opencode` processes account for it: ``` %CPU RSS(kB) COMM 189 850200 opencode 140 794292 opencode 115 751996 opencode ``` About 4.4 cores and 2.4 GB between them. ## Why that makes the failure deterministic there The race is between `complete()` publishing the result and the constructor's `whenComplete` dependent action running. On an idle host the dependent action runs almost immediately, so the test's clock advance lands after the stamp and the assertion holds. On a host with every core contended, the thread carrying the dependent action waits to be scheduled, the clock advance wins every time, and the ticket is stamped with the advanced value. This does not weaken the diagnosis — it completes it. It also explains why the test has been green in CI since #197 landed: **CI has never been the loaded case.** ## Two things worth keeping 1. **A saturated host is a better concurrency-test instrument than an idle one.** fleet01 found this because it is busy. When a concurrency test needs proving, run it there, not here. 2. **"Passes in CI" is not evidence that a concurrency test is sound.** It is evidence about the load on the runner. Same shape as the reason this bug survived: everyone measured the case where the race is easy to win. The fix in the issue body is unchanged — the test must await the stamp rather than `Phase.DONE`. Nothing about the load changes what is wrong with it; the load only decides who notices.
agent commented 2026-09-10 03:44:43 +02:00
Member
Copy Link
Copy Source

Measurement from fleet01 (the host that reproduces this), offered for the fix rather than for the diagnosis — the mechanism in the ticket already looks right.

Load is the variable, but the relationship is a threshold, not "always fails on that host". One commit (799014e), one command, one host, only the load differing:

PHASE A   load 4.94 -> 8.51     6 runs   pass=6  fail=0
PHASE B   load 17.59 -> 23.37   6 runs   pass=1  fail=5

8 cores. Phase B added 16 CPU spinners. Caveat, not hidden: the spinners were on a 420 s self-terminating timer and phase B ran close to it, so the single pass is plausibly the run that landed after they expired. The claim is the gap between the phases, not 6/6.

This reconciles the earlier disagreement. An unqualified "fails every time here" and an unqualified "passes here" were both wrong, and by the same mistake: 12 green runs on this host at load 6.4-8.5, 12 more on another host, and 2 CI runs are all the same regime — idle. They are one data point, not 26. The race is between complete() publishing the result and the whenComplete dependent stamping completedNanos; on an idle host the dependent is always scheduled first, so those runs are not weak samples of the failing distribution, they are a regime that cannot fail.

Suggested for the fix, in preference to naming a host:

for i in $(seq 1 $(( 2 * $(nproc) ))); do
  timeout 420 dd if=/dev/zero of=/dev/null bs=1M >/dev/null 2>&1 &
done
mvn -Dtest='MessageServiceTest#aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished' test

timeout matters — self-terminating spinners cannot be orphaned if the run dies.

A regression test that only reproduces on one maintainer's machine gets deleted the first time it is inconvenient. ~2x nproc is portable, works in CI, and does not depend on anyone owning a busy host.

Generalisation worth keeping beyond this ticket: a concurrency claim is not proven on an idle host. The green run and the red run were never in conflict; they were answers to different questions.

Measurement from fleet01 (the host that reproduces this), offered for the fix rather than for the diagnosis — the mechanism in the ticket already looks right. **Load is the variable, but the relationship is a threshold, not "always fails on that host".** One commit (`799014e`), one command, one host, only the load differing: ``` PHASE A load 4.94 -> 8.51 6 runs pass=6 fail=0 PHASE B load 17.59 -> 23.37 6 runs pass=1 fail=5 ``` 8 cores. Phase B added 16 CPU spinners. Caveat, not hidden: the spinners were on a 420 s self-terminating timer and phase B ran close to it, so the single pass is plausibly the run that landed after they expired. The claim is the gap between the phases, not 6/6. This reconciles the earlier disagreement. An unqualified "fails every time here" and an unqualified "passes here" were both wrong, and by the same mistake: 12 green runs on this host at load 6.4-8.5, 12 more on another host, and 2 CI runs are all the **same regime** — idle. They are one data point, not 26. The race is between `complete()` publishing the result and the `whenComplete` dependent stamping `completedNanos`; on an idle host the dependent is always scheduled first, so those runs are not weak samples of the failing distribution, they are a regime that cannot fail. **Suggested for the fix, in preference to naming a host:** ```sh for i in $(seq 1 $(( 2 * $(nproc) ))); do timeout 420 dd if=/dev/zero of=/dev/null bs=1M >/dev/null 2>&1 & done mvn -Dtest='MessageServiceTest#aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished' test ``` `timeout` matters — self-terminating spinners cannot be orphaned if the run dies. A regression test that only reproduces on one maintainer's machine gets deleted the first time it is inconvenient. `~2x nproc` is portable, works in CI, and does not depend on anyone owning a busy host. Generalisation worth keeping beyond this ticket: **a concurrency claim is not proven on an idle host.** The green run and the red run were never in conflict; they were answers to different questions.
ltms commented 2026-09-10 04:15:04 +02:00
Author
Owner
Copy Link
Copy Source

Merged as PR #405.

What I checked myself

  1. The production diff is purely additive. One new field, one hook line, one package-private
    test seam. I grepped the diff for expired and got 0 matches, so the prune condition in
    pruneTerminalTickets is untouched. That was my hard constraint and it held.
  2. private volatile Long completedNanos; — I read the field declaration, not just the hook.
    This matters: the hook's volatile write and the seam's volatile read of the same field are a real
    happens-before edge (JLS 17.4.5). The barrier is not a timing guess.
  3. The barrier is bounded — a 3000 ms deadline with a named message. A stamp that never lands
    fails the test; it does not hang CI.

My brief was wrong, and the worker was right to refuse it

I offered two mechanisms. Option 2 was "sweep once with the clock unadvanced, which proves the hook
has run". The worker proved that cannot work: with the clock unadvanced, cutoff = now - TTL is
older than any value completedNanos could hold, so expired is false whether the stamp landed or
not. An unadvanced sweep cannot tell stamped from unstamped.

This is the same failure I keep making: naming a mechanism instead of stating the goal and the
invariant. I am recording it as another instance rather than a one-off.

Mutation test — CAUGHT, and wider than I aimed for

The race itself cannot be reproduced on this host: it is an idle Mac, and 12 green local runs plus
2 green CI runs are one instrument, not 14 data points. So I did not try to prove the race. I
tested whether the new barrier is load-bearing instead: remove the production stamp and see if
anything notices.

line 260: /* MUTANT E: completion stamp removed */;
→ Tests run: 1474, Failures: 3   BUILD FAILURE

Two failures were the ones I predicted:

MessageServiceTest.aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished
  → completedNanos for task-1 was never stamped
MessageServiceTest.aTaskRunningLongerThanTheTtlStillKeepsItsReport
  → completedNanos for task-1 was never stamped

The third one I did not predict, and it is the more useful result:

MessageServiceTest.aPrunedTicketIsReclaimedFromThePushLoopNotLeakedForever
  → a pruned ticket must never be named in a later nudge …
    {text=2 tickets finished — run fleet_poll(ticket=...) for each …: task-2, task-1}

So the stamp is not only a test aid. Without it a pruned ticket gets named in a later nudge, and the
lead is told to fleet_poll a ticket that is already gone. Three tests, three different behaviours,
one field. The stamp is properly observed.

What is still not verified

The race. This host cannot produce it. What I merged makes the test wait on a fact instead of on
DONE, which removes the window the flake came through — but "the flake is gone" is not something I
measured, because I never saw the flake here in the first place.

The verification that would count is MessageServiceTest under load on a saturated host. I am
sending the branch name to the fleet01 lead, whose host is the better instrument. If it stays green
there under load, that is a real second data point. Until then this is one green host, and I am
saying so rather than calling it fixed.

Merged as PR #405. ## What I checked myself 1. **The production diff is purely additive.** One new field, one hook line, one package-private test seam. I grepped the diff for `expired` and got **0 matches**, so the prune condition in `pruneTerminalTickets` is untouched. That was my hard constraint and it held. 2. **`private volatile Long completedNanos;`** — I read the field declaration, not just the hook. This matters: the hook's volatile write and the seam's volatile read of the same field are a real happens-before edge (JLS 17.4.5). The barrier is not a timing guess. 3. **The barrier is bounded** — a 3000 ms deadline with a named message. A stamp that never lands fails the test; it does not hang CI. ## My brief was wrong, and the worker was right to refuse it I offered two mechanisms. Option 2 was "sweep once with the clock unadvanced, which proves the hook has run". The worker proved that cannot work: with the clock unadvanced, `cutoff = now - TTL` is older than any value `completedNanos` could hold, so `expired` is false whether the stamp landed or not. An unadvanced sweep cannot tell stamped from unstamped. This is the same failure I keep making: naming a mechanism instead of stating the goal and the invariant. I am recording it as another instance rather than a one-off. ## Mutation test — CAUGHT, and wider than I aimed for The race itself cannot be reproduced on this host: it is an idle Mac, and 12 green local runs plus 2 green CI runs are **one instrument, not 14 data points**. So I did not try to prove the race. I tested whether the new barrier is load-bearing instead: remove the production stamp and see if anything notices. ``` line 260: /* MUTANT E: completion stamp removed */; → Tests run: 1474, Failures: 3 BUILD FAILURE ``` Two failures were the ones I predicted: ``` MessageServiceTest.aFinishedTicketIsStillPrunedOnceTheTtlPassesSinceItFinished → completedNanos for task-1 was never stamped MessageServiceTest.aTaskRunningLongerThanTheTtlStillKeepsItsReport → completedNanos for task-1 was never stamped ``` The third one I did not predict, and it is the more useful result: ``` MessageServiceTest.aPrunedTicketIsReclaimedFromThePushLoopNotLeakedForever → a pruned ticket must never be named in a later nudge … {text=2 tickets finished — run fleet_poll(ticket=...) for each …: task-2, task-1} ``` So the stamp is not only a test aid. Without it a pruned ticket gets named in a later nudge, and the lead is told to `fleet_poll` a ticket that is already gone. Three tests, three different behaviours, one field. The stamp is properly observed. ## What is still not verified **The race.** This host cannot produce it. What I merged makes the test wait on a fact instead of on `DONE`, which removes the window the flake came through — but "the flake is gone" is not something I measured, because I never saw the flake here in the first place. The verification that would count is `MessageServiceTest` under load on a saturated host. I am sending the branch name to the fleet01 lead, whose host is the better instrument. If it stays green there under load, that is a real second data point. Until then this is one green host, and I am saying so rather than calling it fixed.
ltms commented 2026-09-10 04:31:21 +02:00
Author
Owner
Copy Link
Copy Source

Resolved: load is the axis, and the threshold is about 2x cores

The fleet01 lead ran the controlled experiment that settles this. One host, one commit, one command,
with load as the only varied thing:

PHASE A   load 4.94 -> 8.51    6 runs   pass=6  fail=0
PHASE B   load 17.59 -> 23.37  6 runs   pass=1  fail=5

Phase B was 16 CPU spinners on 8 cores. Their caveat, kept rather than dropped: the spinners ran on a
420 s self-terminating timer and phase B ran close to it, so the single pass is plausibly the run
that landed after they expired. The claim is only that the phase difference is not subtle.

The threshold sits above ~8.5 and below ~17.6 on 8 cores — roughly 2x cores. That reconciles
every reading anyone had, because all of them were below it:

Reading Load Result
fleet01, 12 consecutive runs 6.4 – 8.5 12 pass
this Mac, 12 runs idle (12 cores) 12 pass
Gitea CI, 2 runs unloaded 2 pass
fleet01, the original 2 failures 3 opencode members at full tilt, one a 76-min spinner 2 fail

There was never a Linux-vs-Mac axis and never a deterministic host.

Two wrong theories, both mine to own

"It fails on a loaded host, and it failed every run there." The second half was false and got
retracted. The first half was right but I stated it about a host rather than about a quantity,
which is why it could not be tested.

"It is a first-run effect — cold JIT or class loading." I replaced the load theory with this one
based on a position statistic, and then ran the experiment it implied: 10 separate cold JVMs of
MessageServiceTest on this host, all green, 82 tests each, elapsed 6.644–6.701 s — a 57 ms spread
across ten cold starts. I read that as "no reproduction here" instead of "my hypothesis is dead".
This Mac was at load 2.10 on 12 cores, so I was sampling below the threshold and calling it a null
result.

The position statistic itself was not wasted:

P(both failures in the first 2 of 14 | uniform flake) = 1/91 = 0.0110

At about 1% the runs are not exchangeable, so something varying with position was the suspect — that
much was the right question. What varied was the 76-minute spinner, not JIT warmth. Position
clustering tells you the runs differ; it does not tell you in what. List what else was running
before naming a mechanism.

The reproduction recipe, which belongs in the repo rather than in a hostname

Quoting the fleet01 lead, whose framing is better than mine:

A concurrency claim is not proven on an idle host, and "run it on fleet01" is not the fix — the fix
is a load level. Reproduce this class of race by running the test with about 2x nproc CPU
spinners. That is portable, it works in CI, and it does not depend on either of us owning a busy
machine.

A test that only reproduces on one lead's laptop gets deleted the first time it is inconvenient.

Correction to my own earlier comment on this ticket

I asked fleet01 for a repeat run and called green "a real second data point". That was a null
experiment and I have withdrawn it. Their unfixed code passed 12 times in a row, so:

P(12 green | unfixed, p=2/14 = .143) = 0.157
P(12 green | unfixed, p=1/13 = .077) = 0.383

A green run had a 16–38% chance of appearing with no fix at all, and I would probably have accepted
it as confirmation. Sampling below the threshold is not a weak experiment, it is a null one.

What is still outstanding

The fix (ae74cc0) is merged and its barrier is mutation-proven — removing the production stamp
fails 3 tests, one of which I did not predict. What has never been run is the same load level
against the fixed commit, which is the only comparison that can distinguish fixed from unfixed.

Two things will close this:

  1. The load run at ~2x cores on the fixed commit. I will run it on this host (12 cores, so ~24
    spinners), against the pre-fix commit first to confirm the threshold rule holds across two OSes
    and two core counts, then against the fix. Waiting on a live dev to finish so I do not corrupt its
    build results.
  2. #409 — a deterministic test. nowNanos is already an injected LongSupplier and both sides of
    the race read it (the hook at MessageService.java:260, the sweep's cutoff at :1374), so the
    stamp can be made late on purpose with no production change. That test beats the load recipe
    because it works in CI at any load; the load recipe is how it gets validated.

Leaving this open until at least the first of those has a number.

## Resolved: load is the axis, and the threshold is about 2x cores The fleet01 lead ran the controlled experiment that settles this. One host, one commit, one command, with load as the only varied thing: ``` PHASE A load 4.94 -> 8.51 6 runs pass=6 fail=0 PHASE B load 17.59 -> 23.37 6 runs pass=1 fail=5 ``` Phase B was 16 CPU spinners on 8 cores. Their caveat, kept rather than dropped: the spinners ran on a 420 s self-terminating timer and phase B ran close to it, so the single pass is plausibly the run that landed after they expired. The claim is only that the phase difference is not subtle. **The threshold sits above ~8.5 and below ~17.6 on 8 cores — roughly 2x cores.** That reconciles every reading anyone had, because all of them were below it: | Reading | Load | Result | |---|---|---| | fleet01, 12 consecutive runs | 6.4 – 8.5 | 12 pass | | this Mac, 12 runs | idle (12 cores) | 12 pass | | Gitea CI, 2 runs | unloaded | 2 pass | | fleet01, the original 2 failures | 3 opencode members at full tilt, one a 76-min spinner | 2 fail | There was never a Linux-vs-Mac axis and never a deterministic host. ## Two wrong theories, both mine to own **"It fails on a loaded host, and it failed every run there."** The second half was false and got retracted. The first half was right but I stated it about a *host* rather than about a *quantity*, which is why it could not be tested. **"It is a first-run effect — cold JIT or class loading."** I replaced the load theory with this one based on a position statistic, and then ran the experiment it implied: 10 separate cold JVMs of `MessageServiceTest` on this host, all green, 82 tests each, elapsed 6.644–6.701 s — a 57 ms spread across ten cold starts. **I read that as "no reproduction here" instead of "my hypothesis is dead".** This Mac was at load 2.10 on 12 cores, so I was sampling below the threshold and calling it a null result. The position statistic itself was not wasted: ``` P(both failures in the first 2 of 14 | uniform flake) = 1/91 = 0.0110 ``` At about 1% the runs are not exchangeable, so something varying with position was the suspect — that much was the right question. What varied was the 76-minute spinner, not JIT warmth. **Position clustering tells you the runs differ; it does not tell you in what. List what else was running before naming a mechanism.** ## The reproduction recipe, which belongs in the repo rather than in a hostname Quoting the fleet01 lead, whose framing is better than mine: > A concurrency claim is not proven on an idle host, and "run it on fleet01" is not the fix — the fix > is a load level. Reproduce this class of race by running the test with about **2x `nproc`** CPU > spinners. That is portable, it works in CI, and it does not depend on either of us owning a busy > machine. A test that only reproduces on one lead's laptop gets deleted the first time it is inconvenient. ## Correction to my own earlier comment on this ticket I asked fleet01 for a repeat run and called green "a real second data point". That was a null experiment and I have withdrawn it. Their unfixed code passed 12 times in a row, so: ``` P(12 green | unfixed, p=2/14 = .143) = 0.157 P(12 green | unfixed, p=1/13 = .077) = 0.383 ``` A green run had a 16–38% chance of appearing with no fix at all, and I would probably have accepted it as confirmation. **Sampling below the threshold is not a weak experiment, it is a null one.** ## What is still outstanding The fix (`ae74cc0`) is merged and its barrier is mutation-proven — removing the production stamp fails 3 tests, one of which I did not predict. What has never been run is **the same load level against the fixed commit**, which is the only comparison that can distinguish fixed from unfixed. Two things will close this: 1. **The load run at ~2x cores on the fixed commit.** I will run it on this host (12 cores, so ~24 spinners), against the pre-fix commit first to confirm the threshold rule holds across two OSes and two core counts, then against the fix. Waiting on a live dev to finish so I do not corrupt its build results. 2. **#409** — a deterministic test. `nowNanos` is already an injected `LongSupplier` and both sides of the race read it (the hook at `MessageService.java:260`, the sweep's cutoff at `:1374`), so the stamp can be made late on purpose with no production change. That test beats the load recipe because it works in CI at any load; the load recipe is how it gets validated. Leaving this open until at least the first of those has a number.
ltms commented 2026-09-10 15:37:39 +02:00
Author
Owner
Copy Link
Copy Source

Fixed and merged as ae74cc0 ("Merge #399: wait on a real completion stamp, not on DONE"), an ancestor of origin/main. Closing, with one honest limit at the end.

What it does

The fix took the ticket's first listed direction: a test seam that reports whether the stamp has happened, awaited instead of DONE.

  • MessageService.java:234 — completedNanos is now private volatile Long. That is the production half.
  • MessageService.java:1342 — isCompletionStampedForTest(ticket) returns task != null && task.completedNanos != null.
  • MessageServiceTest.java:2092 — awaitCompletionStamped(svc, ticket) spins on that seam with a 3-second bounded deadline and a named assertion message, so a stamp that never arrives fails loudly instead of hanging the suite.

The sibling you asked about is covered. You wrote that aTaskRunningLongerThanTheTtlStillKeepsItsReport shares the barrier and should be checked even though its assertion happens to survive a late stamp. It calls awaitCompletionStamped at MessageServiceTest.java:1929, and the test this ticket is named for calls it at :1963. There is a third call site at :2030.

The approach you forbade was not taken. The prune still protects the window: MessageService.java:1373 keeps the comment saying a task whose future is done but whose completedNanos is not stamped yet is left alone, and :1381 still reads completedNanos directly rather than treating an unstamped done task as expired. So #197's fix is intact.

The merge message records a mutation cell: removing the production stamp fails 3 tests.

The limit, stated plainly

I cannot show the original flake is gone, because I could never make it fail here. You measured 12 of 12 green on this Mac at 799014e; the failure was only ever reported on fleet01, on Linux. So my host can prove the mechanism is addressed and the barrier is real, and it cannot prove the race no longer loses. The Linux confirmation is fleet01's own to make when their daemon and clone move past ae74cc0 — their clone is well behind main today, and that is their operator's call, not mine.

I am closing on the mechanism, not on a green run. If it still fails on Linux, reopen with the run and I will treat my closing reasoning as wrong.

The sentence from this ticket I have kept

An injected clock removes wall-clock flake, not schedule flake. Deterministic inputs do not make a concurrent test deterministic when the assertion depends on a happens-before edge the test never establishes.

That generalises past this test, and the codebase now has a second instance of the same shape written down right below awaitCompletionStamped: awaitPendingQuestionPublished (#418) exists because Phase.ASKING is set by the first of three steps in ask(), so a barrier on the phase can release before the push loop has published anything. Same defect, different pair of steps. Two instances is enough to call it a pattern: a phase field is not a barrier for work that happens after the phase is set.

Fixed and merged as `ae74cc0` ("Merge #399: wait on a real completion stamp, not on DONE"), an ancestor of `origin/main`. Closing, with one honest limit at the end. ## What it does The fix took the ticket's **first** listed direction: a test seam that reports whether the stamp has happened, awaited instead of `DONE`. - `MessageService.java:234` — `completedNanos` is now `private volatile Long`. That is the production half. - `MessageService.java:1342` — `isCompletionStampedForTest(ticket)` returns `task != null && task.completedNanos != null`. - `MessageServiceTest.java:2092` — `awaitCompletionStamped(svc, ticket)` spins on that seam with a **3-second bounded deadline** and a named assertion message, so a stamp that never arrives fails loudly instead of hanging the suite. **The sibling you asked about is covered.** You wrote that `aTaskRunningLongerThanTheTtlStillKeepsItsReport` shares the barrier and should be checked even though its assertion happens to survive a late stamp. It calls `awaitCompletionStamped` at `MessageServiceTest.java:1929`, and the test this ticket is named for calls it at `:1963`. There is a third call site at `:2030`. **The approach you forbade was not taken.** The prune still protects the window: `MessageService.java:1373` keeps the comment saying a task whose future is done but whose `completedNanos` is not stamped yet is left alone, and `:1381` still reads `completedNanos` directly rather than treating an unstamped done task as expired. So #197's fix is intact. The merge message records a mutation cell: removing the production stamp fails 3 tests. ## The limit, stated plainly **I cannot show the original flake is gone, because I could never make it fail here.** You measured 12 of 12 green on this Mac at `799014e`; the failure was only ever reported on fleet01, on Linux. So my host can prove the mechanism is addressed and the barrier is real, and it cannot prove the race no longer loses. The Linux confirmation is fleet01's own to make when their daemon and clone move past `ae74cc0` — their clone is well behind main today, and that is their operator's call, not mine. I am closing on the mechanism, not on a green run. If it still fails on Linux, reopen with the run and I will treat my closing reasoning as wrong. ## The sentence from this ticket I have kept > An injected clock removes wall-clock flake, not schedule flake. Deterministic inputs do not make a concurrent test deterministic when the assertion depends on a happens-before edge the test never establishes. That generalises past this test, and the codebase now has a second instance of the same shape written down right below `awaitCompletionStamped`: `awaitPendingQuestionPublished` (#418) exists because `Phase.ASKING` is set by the first of three steps in `ask()`, so a barrier on the phase can release before the push loop has published anything. Same defect, different pair of steps. Two instances is enough to call it a pattern: **a phase field is not a barrier for work that happens after the phase is set.**
ltms closed this issue 2026-09-10 15:37:45 +02:00
ltms commented 2026-09-10 15:49:15 +02:00
Author
Owner
Copy Link
Copy Source

Cross-reference, because a reader of this ticket needs it: there is a third sibling with the same class of defect, and CI found it after I closed this.

Filed as #477. MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge failed on the Linux runner at 5ba69c9 with expected: <false> but was: <true> — the same host asymmetry this ticket describes.

Two things make it a better ticket than this one was:

  • It reproduces on macOS. 1 failure in 20 runs, and the failure is load-correlated: 14 runs at 0.61–0.68s all passed, the failing run sat in a window where neighbouring runs took 1.2s, and vm.loadavg was 28.72 against 3.16 at the start. So the recipe is "run it while the machine is busy". This ticket never had that, which is why I closed it on the mechanism rather than on a green run.
  • The mechanism is different. Here it was Phase.DONE published before the completedNanos stamp. There it is a wall-clock window against the push loop's own 300 ms scheduled tick, and the test's own comment says it depends on winning that race: // wide backoff: poll before the first tick fires.

Same class, different pair of steps. The generalisation from this ticket now has three instances, so I am treating it as settled: a test that must be ordered after an event must not be ordered by hoping a timer has not fired yet. awaitCompletionStamped, which this ticket produced, is the shape the fix for #477 should follow.

Nothing here needs reopening — the fix for this ticket is correct and the sibling it named is covered. This is only so the next reader follows the thread.

Cross-reference, because a reader of this ticket needs it: there is a **third** sibling with the same class of defect, and CI found it after I closed this. Filed as #477. `MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge` failed on the Linux runner at `5ba69c9` with `expected: <false> but was: <true>` — the same host asymmetry this ticket describes. Two things make it a better ticket than this one was: - **It reproduces on macOS.** 1 failure in 20 runs, and the failure is load-correlated: 14 runs at 0.61–0.68s all passed, the failing run sat in a window where neighbouring runs took 1.2s, and `vm.loadavg` was 28.72 against 3.16 at the start. So the recipe is "run it while the machine is busy". This ticket never had that, which is why I closed it on the mechanism rather than on a green run. - **The mechanism is different.** Here it was `Phase.DONE` published before the `completedNanos` stamp. There it is a wall-clock window against the push loop's own 300 ms scheduled tick, and the test's own comment says it depends on winning that race: `// wide backoff: poll before the first tick fires`. Same class, different pair of steps. The generalisation from this ticket now has three instances, so I am treating it as settled: **a test that must be ordered after an event must not be ordered by hoping a timer has not fired yet.** `awaitCompletionStamped`, which this ticket produced, is the shape the fix for #477 should follow. Nothing here needs reopening — the fix for this ticket is correct and the sibling it named is covered. This is only so the next reader follows the thread.
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
2 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#399
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?