Flaky: MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge orders an async scheduler with Thread.sleep #608

Closed
opened 2026-09-20 11:41:48 +02:00 by ltms · 1 comment
Owner

What I measured

Building main at 9a992d0 on a loaded machine (three worker sessions and their builds running at the same time):

run scope result
1 full suite FAILED — 1841 tests, 1 failure
2 -Dtest=MessageServiceTest passed, 89/89
3 -Dtest=MessageServiceTest passed, 89/89
4 -Dtest=MessageServiceTest passed, 89/89
5 full suite passed — 1841 tests, 0 failures

The failure:

dev.ltms.fleet.msg.MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge
org.opentest4j.AssertionFailedError: a ticket the lead already polled must never be nudged
  ==> expected: <false> but was: <true>
  at MessageServiceTest.java:1895

Reports were confirmed fresh by mtime, so runs 2–4 really executed rather than reusing an earlier result.

Why it is flaky

try (var wiring = wireWithPushLoop(1, 300)) { // wide backoff: poll before the first tick fires
    ...
    Thread.sleep(400); // let the scheduled tick run — it must find nothing pending
    assertFalse(wiring.leadHerdr().called("agent.prompt"), ...);
}

The test orders a scheduled background tick against the assertion using wall-clock sleeps: a 300 ms backoff, and the work in between expected to finish inside it. The comment states the assumption out loud — "wide backoff: poll before the first tick fires".

On an idle machine that holds. Under load it does not. If the tick fires before the poll has marked the ticket collected, a nudge is emitted and the assertion is correct to fail. Nothing in the test forces that ordering; it only makes it likely.

Why this is worth fixing rather than re-running

A test that usually passes is not a weaker test — it is a test that sometimes lies, and it lies in the direction that gets believed. A green suite is the gate for merging and redeploying here, so an occasional red with no attached cause trains everyone to re-run and move on. The next time this test goes red it may be reporting a real race and it will look exactly the same.

Note also what the test is about: whether an already-collected ticket can still nudge the lead's pane. If the ordering it cannot control is also unforced in production, the flake may be pointing at a real race in the nudge path, not only at the test. That is worth deciding rather than assuming — the test passing on a quiet machine does not answer it.

Suggested direction

Replace the wall-clock ordering with something deterministic. The codebase already does this elsewhere: LeadContextGauge takes an injectable LongSupplier clock, and LeadRollover takes an injectable clock and sleeper, precisely so timing can be asserted without sleeping. Driving the tick explicitly, or gating it on a latch the test releases, removes the race instead of making it rarer.

Do not fix it by widening the sleep. That lowers the failure rate without removing the race, and it slows the suite on every run to hide a fault that appears on some.

Acceptance should be a property: with the tick forced to fire before the poll completes, the test must still express the right expectation — either it passes because the production code genuinely suppresses the nudge, or it fails and has found a real defect. Right now that ordering is untestable, so we cannot tell which.

Not a regression

MessageService.java and MessageServiceTest.java were untouched by today's merges (#602, #605, #606, #607). The test last changed on 2026-09-12 in c1e06c9. This is pre-existing and was surfaced by load, not introduced.

## What I measured Building `main` at `9a992d0` on a loaded machine (three worker sessions and their builds running at the same time): | run | scope | result | |---|---|---| | 1 | full suite | **FAILED** — 1841 tests, 1 failure | | 2 | `-Dtest=MessageServiceTest` | passed, 89/89 | | 3 | `-Dtest=MessageServiceTest` | passed, 89/89 | | 4 | `-Dtest=MessageServiceTest` | passed, 89/89 | | 5 | full suite | passed — 1841 tests, 0 failures | The failure: ``` dev.ltms.fleet.msg.MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge org.opentest4j.AssertionFailedError: a ticket the lead already polled must never be nudged ==> expected: <false> but was: <true> at MessageServiceTest.java:1895 ``` Reports were confirmed fresh by mtime, so runs 2–4 really executed rather than reusing an earlier result. ## Why it is flaky ```java try (var wiring = wireWithPushLoop(1, 300)) { // wide backoff: poll before the first tick fires ... Thread.sleep(400); // let the scheduled tick run — it must find nothing pending assertFalse(wiring.leadHerdr().called("agent.prompt"), ...); } ``` The test orders a scheduled background tick against the assertion using wall-clock sleeps: a 300 ms backoff, and the work in between expected to finish inside it. The comment states the assumption out loud — *"wide backoff: poll before the first tick fires"*. On an idle machine that holds. Under load it does not. If the tick fires before the poll has marked the ticket collected, a nudge is emitted and the assertion is correct to fail. Nothing in the test forces that ordering; it only makes it likely. ## Why this is worth fixing rather than re-running A test that usually passes is not a weaker test — it is a test that sometimes lies, and it lies in the direction that gets believed. A green suite is the gate for merging and redeploying here, so an occasional red with no attached cause trains everyone to re-run and move on. The next time this test goes red it may be reporting a real race and it will look exactly the same. Note also what the test is about: whether an already-collected ticket can still nudge the lead's pane. If the ordering it cannot control is also unforced in production, the flake may be pointing at a real race in the nudge path, not only at the test. That is worth deciding rather than assuming — the test passing on a quiet machine does not answer it. ## Suggested direction Replace the wall-clock ordering with something deterministic. The codebase already does this elsewhere: `LeadContextGauge` takes an injectable `LongSupplier clock`, and `LeadRollover` takes an injectable clock and sleeper, precisely so timing can be asserted without sleeping. Driving the tick explicitly, or gating it on a latch the test releases, removes the race instead of making it rarer. Do not fix it by widening the sleep. That lowers the failure rate without removing the race, and it slows the suite on every run to hide a fault that appears on some. Acceptance should be a property: with the tick forced to fire **before** the poll completes, the test must still express the right expectation — either it passes because the production code genuinely suppresses the nudge, or it fails and has found a real defect. Right now that ordering is untestable, so we cannot tell which. ## Not a regression `MessageService.java` and `MessageServiceTest.java` were untouched by today's merges (#602, #605, #606, #607). The test last changed on 2026-09-12 in `c1e06c9`. This is pre-existing and was surfaced by load, not introduced.
ltms closed this issue 2026-09-20 12:27:31 +02:00
Author
Owner

Closed by #611, merged as fa62e99.

Merged main built clean in a fresh worktree: 1841 tests, 0 failures, 0 errors, exit 0.

Why I consider this fixed rather than "it passed again"

N green runs never prove a flake is gone — that is the same wall-clock bet the defect was made
of, just taken from the other side. What closes this is that the race is structurally removed,
not that it stopped reproducing.

ManualScheduler is a ScheduledExecutorService that never fires on a timer. The tick runs only
when the test calls runDueTasks(). The rewritten test sets backoffMs to 1 — the most hostile
value there is, the tick due immediately — and still passes, because no backoff value can make a
tick fire that nothing schedules. There is no longer any ordering for load to disturb.

The fake implements only the two methods ReplyPushLoop actually calls and throws
UnsupportedOperationException from the other fourteen, so a future change that starts calling
one fails loudly instead of being quietly mishandled.

The question this ticket raised is answered

I asked whether the flake might be pointing at a real race in the nudge path rather than only in
the test. It is not. The production guard is real and the test can prove it: mutating
ReplyPushLoop.ticketCollected to a no-op makes the rewritten test go red with the same
assertion message as the original flake.

dev.ltms.fleet.msg.MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge -- FAILURE!
org.opentest4j.AssertionFailedError: a ticket the lead already polled must never be nudged
  ==> expected: <false> but was: <true>

So the test can still go red for the right reason, which is the half that matters — a test that
cannot fail is not worth making deterministic.

One thing I checked and got wrong

I ran my own independent mutation, forcing hasTicketWork = true in ReplyPushLoop.decide, and
it survived. That is not a coverage gap. injectNudge re-reads all five pending collections
and returns early when they are empty:

if (replyTargets.isEmpty() && tickets.isEmpty() && questions.isEmpty() && incidents.isEmpty()
        && unmappedTargets.isEmpty()) {
    log.debug("push: pending work for lead {} drained before the nudge could be sent", lead);
    return;
}

My mutation lies only to decide; the sender checks reality again and sends nothing. It is an
equivalent mutant with respect to agent.prompt, which is the observable under assertion. Worth
recording, because it means there are two independent guards here and only one of them is
reachable from this test's observable.

Same shape elsewhere, not fixed

Two other sleeps in MessageServiceTest are the same bet and can go red on correct code under
load: lines 1910 and 1916, both inside
severalAsyncTicketsFinishingTogetherProduceOneCoalescedNudge, which needs both tickets to land
inside the 300 ms backoff before the tick fires.

Three more were checked and are not the same shape: line 1919 can only produce a false green
(it waits to confirm nothing extra arrives), and lines 2020 and 2112 both follow a state that has
already settled deterministically.

Deliberately left alone. Converting them is a separate unit, and ManualScheduler now exists for
whoever takes it.

Closed by #611, merged as `fa62e99`. Merged `main` built clean in a fresh worktree: **1841 tests, 0 failures, 0 errors**, exit 0. ## Why I consider this fixed rather than "it passed again" N green runs never prove a flake is gone — that is the same wall-clock bet the defect was made of, just taken from the other side. What closes this is that **the race is structurally removed**, not that it stopped reproducing. `ManualScheduler` is a `ScheduledExecutorService` that never fires on a timer. The tick runs only when the test calls `runDueTasks()`. The rewritten test sets `backoffMs` to `1` — the most hostile value there is, the tick due immediately — and still passes, because no backoff value can make a tick fire that nothing schedules. There is no longer any ordering for load to disturb. The fake implements only the two methods `ReplyPushLoop` actually calls and throws `UnsupportedOperationException` from the other fourteen, so a future change that starts calling one fails loudly instead of being quietly mishandled. ## The question this ticket raised is answered I asked whether the flake might be pointing at a real race in the nudge path rather than only in the test. It is not. The production guard is real and the test can prove it: mutating `ReplyPushLoop.ticketCollected` to a no-op makes the rewritten test go red with the same assertion message as the original flake. ``` dev.ltms.fleet.msg.MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge -- FAILURE! org.opentest4j.AssertionFailedError: a ticket the lead already polled must never be nudged ==> expected: <false> but was: <true> ``` So the test can still go red for the right reason, which is the half that matters — a test that cannot fail is not worth making deterministic. ## One thing I checked and got wrong I ran my own independent mutation, forcing `hasTicketWork = true` in `ReplyPushLoop.decide`, and it **survived**. That is not a coverage gap. `injectNudge` re-reads all five pending collections and returns early when they are empty: ```java if (replyTargets.isEmpty() && tickets.isEmpty() && questions.isEmpty() && incidents.isEmpty() && unmappedTargets.isEmpty()) { log.debug("push: pending work for lead {} drained before the nudge could be sent", lead); return; } ``` My mutation lies only to `decide`; the sender checks reality again and sends nothing. It is an equivalent mutant with respect to `agent.prompt`, which is the observable under assertion. Worth recording, because it means there are two independent guards here and only one of them is reachable from this test's observable. ## Same shape elsewhere, not fixed Two other sleeps in `MessageServiceTest` are the same bet and can go red on correct code under load: lines 1910 and 1916, both inside `severalAsyncTicketsFinishingTogetherProduceOneCoalescedNudge`, which needs both tickets to land inside the 300 ms backoff before the tick fires. Three more were checked and are **not** the same shape: line 1919 can only produce a false green (it waits to confirm nothing extra arrives), and lines 2020 and 2112 both follow a state that has already settled deterministically. Deliberately left alone. Converting them is a separate unit, and `ManualScheduler` now exists for whoever takes it.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#608