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

CB-601: AmqpReplyInboxRecoveryRaceTest is non-deterministic — it fails on main under load, and the production code is correct #95

New Issue
Closed
opened 2026-08-16 17:52:10 +02:00 by ltms · 2 comments
ltms commented 2026-08-16 17:52:10 +02:00
Owner
Copy Link
Copy Source

main is red under load right now. This is a test defect, not a code defect — I merged it in #88, so it is mine to correct.

How it surfaced

A worker doing unrelated documentation work (CB-597) ran mvn clean install and got:

[ERROR] Tests run: 816, Failures: 1, Errors: 0, Skipped: 0  → BUILD FAILURE

It checked the failure against an unmodified origin/main worktree before reporting, and reproduced it 3/3 there. That was exactly the right instinct and it is why this ticket exists.

I could not reproduce it: 3/3 passes on the same commit on the same host, ~4.4s each. The difference was load — five members and two of my own builds were running during the worker's run.

The failure is real, not a timeout

AmqpReplyInboxRecoveryRaceTest.recoverySweepDoesNotFailAPublishThatRegistersWhileItIsRunning
  -- Time elapsed: 3.826 s <<< FAILURE!
org.opentest4j.AssertionFailedError: a publish that registered while the recovery sweep was running
must not be failed by it, but got: java.lang.IllegalStateException: AMQP connection recovered
mid-publish; confirm status of reply fresh is unknown
  ==> expected: <null> but was: <java.lang.IllegalStateException: ...>
	at AmqpReplyInboxRecoveryRaceTest.recoverySweepDoesNotFailAPublishThatRegistersWhileItIsRunning(AmqpReplyInboxRecoveryRaceTest.java:127)

3.8s against a @Timeout(30), so the 100,000 virtual threads are not the cause. My first theory was that the setup blew the timeout under load; the evidence killed it.

Root cause

The test cannot control the interleaving it asserts on. Its own comment says so:

// A short, deliberate head start: ...
// Without this head start, "fresh" sometimes wins the race for the lock and
// registers before the sweep even starts, which is the accepted "already in flight when
// recovery fires" case (correctly failed either way) rather than the bug under test.
Thread.sleep(5);

publish() and failPendingPublishesOnRecovery() both take publishChannelLock, so exactly one of two interleavings happens, and both are correct:

  1. Sweep takes the lock first → fresh waits, registers on the recovered channel afterwards, and must not be failed. This is what the test asserts.
  2. fresh takes the lock first → it really did go out on the old channel, so the sweep failing it is correct behaviour, by design and as stated in the fix's own javadoc.

A 5 ms Thread.sleep is the only thing steering it toward case 1. Under load the sweep thread is not scheduled inside that window, case 2 happens, and the test reports a bug that is not there.

So the guard added in #88 is correct and should not be touched. Only the test needs fixing.

The fix

Replace the timing-based head start with an observable signal that the sweep is genuinely inside the lock, then start fresh.

The sweep completes each stale Pending exceptionally as it iterates, and every stale publisher thread is already sitting in publish() waiting on its confirm. So the first stale publish to throw is proof the sweep is mid-iteration and holding the lock. Have the stale threads count down a latch when they are failed, await the first one, and only then start fresh. That makes case 1 guaranteed rather than likely, with no sleep.

If a cleaner deterministic signal exists, use it. The requirement is that no Thread.sleep decides which interleaving occurs.

While in there: STALE_PUBLISHES is 100,000 but a comment at line 112 still says "behind the 20,000 stale threads" — a leftover from an earlier value. Also reconsider whether 100,000 is needed at all once the ordering is deterministic; the count exists purely to widen a timing window that the fix removes.

Acceptance criteria

  1. No Thread.sleep determines which thread wins the lock.
  2. The test still fails when the synchronized (publishChannelLock) guard is removed from failPendingPublishesOnRecovery. Prove this by removing the guard, running it, restoring it, and quoting the failure. A race test that cannot detect the bug it was written for is worse than no test.
  3. It passes repeatedly under load. Run it at least 10 times consecutively while a full mvn clean install runs in parallel, and quote the results. Passing on an idle machine is what got us here.
  4. Case 2 — fresh acquiring the lock before the sweep — is either made impossible by construction, or covered by its own test asserting the publish is failed. Do not leave it as an untested silent alternative.
  5. No production code changes. If you conclude the production code is genuinely wrong, stop and report that instead — do not change it on your own judgement.
  6. The stale comment at line 112 matches the real constant.
  7. mvn -f bridged/pom.xml clean install green, unpiped.

Note

CI runs this in the default job, so a loaded CI runner can hit the same failure. That makes it a release blocker for 1.1: an intermittently red main trains people to re-run builds until they go green, which is how a real failure gets ignored.

`main` is red under load right now. This is a **test defect, not a code defect** — I merged it in #88, so it is mine to correct. ## How it surfaced A worker doing unrelated documentation work (CB-597) ran `mvn clean install` and got: ``` [ERROR] Tests run: 816, Failures: 1, Errors: 0, Skipped: 0 → BUILD FAILURE ``` It checked the failure against an unmodified `origin/main` worktree before reporting, and reproduced it 3/3 there. That was exactly the right instinct and it is why this ticket exists. I could not reproduce it: 3/3 passes on the same commit on the same host, ~4.4s each. The difference was load — five members and two of my own builds were running during the worker's run. ## The failure is real, not a timeout ``` AmqpReplyInboxRecoveryRaceTest.recoverySweepDoesNotFailAPublishThatRegistersWhileItIsRunning -- Time elapsed: 3.826 s <<< FAILURE! org.opentest4j.AssertionFailedError: a publish that registered while the recovery sweep was running must not be failed by it, but got: java.lang.IllegalStateException: AMQP connection recovered mid-publish; confirm status of reply fresh is unknown ==> expected: <null> but was: <java.lang.IllegalStateException: ...> at AmqpReplyInboxRecoveryRaceTest.recoverySweepDoesNotFailAPublishThatRegistersWhileItIsRunning(AmqpReplyInboxRecoveryRaceTest.java:127) ``` 3.8s against a `@Timeout(30)`, so the 100,000 virtual threads are not the cause. My first theory was that the setup blew the timeout under load; the evidence killed it. ## Root cause The test cannot control the interleaving it asserts on. Its own comment says so: ```java // A short, deliberate head start: ... // Without this head start, "fresh" sometimes wins the race for the lock and // registers before the sweep even starts, which is the accepted "already in flight when // recovery fires" case (correctly failed either way) rather than the bug under test. Thread.sleep(5); ``` `publish()` and `failPendingPublishesOnRecovery()` both take `publishChannelLock`, so exactly one of two interleavings happens, and **both are correct**: 1. Sweep takes the lock first → `fresh` waits, registers on the recovered channel afterwards, and must **not** be failed. This is what the test asserts. 2. `fresh` takes the lock first → it really did go out on the *old* channel, so the sweep failing it is **correct behaviour**, by design and as stated in the fix's own javadoc. A 5 ms `Thread.sleep` is the only thing steering it toward case 1. Under load the sweep thread is not scheduled inside that window, case 2 happens, and the test reports a bug that is not there. **So the guard added in #88 is correct and should not be touched.** Only the test needs fixing. ## The fix Replace the timing-based head start with an **observable** signal that the sweep is genuinely inside the lock, then start `fresh`. The sweep completes each stale `Pending` exceptionally as it iterates, and every stale publisher thread is already sitting in `publish()` waiting on its confirm. So the first stale publish to throw is proof the sweep is mid-iteration and holding the lock. Have the stale threads count down a latch when they are failed, await the first one, and only then start `fresh`. That makes case 1 guaranteed rather than likely, with no sleep. If a cleaner deterministic signal exists, use it. The requirement is that no `Thread.sleep` decides which interleaving occurs. While in there: `STALE_PUBLISHES` is 100,000 but a comment at line 112 still says "behind the 20,000 stale threads" — a leftover from an earlier value. Also reconsider whether 100,000 is needed at all once the ordering is deterministic; the count exists purely to widen a timing window that the fix removes. ## Acceptance criteria 1. No `Thread.sleep` determines which thread wins the lock. 2. The test still fails when the `synchronized (publishChannelLock)` guard is removed from `failPendingPublishesOnRecovery`. **Prove this** by removing the guard, running it, restoring it, and quoting the failure. A race test that cannot detect the bug it was written for is worse than no test. 3. It passes repeatedly under load. Run it at least 10 times consecutively **while a full `mvn clean install` runs in parallel**, and quote the results. Passing on an idle machine is what got us here. 4. Case 2 — `fresh` acquiring the lock before the sweep — is either made impossible by construction, or covered by its own test asserting the publish **is** failed. Do not leave it as an untested silent alternative. 5. No production code changes. If you conclude the production code is genuinely wrong, stop and report that instead — do not change it on your own judgement. 6. The stale comment at line 112 matches the real constant. 7. `mvn -f bridged/pom.xml clean install` green, unpiped. ## Note CI runs this in the default job, so a loaded CI runner can hit the same failure. That makes it a release blocker for 1.1: an intermittently red `main` trains people to re-run builds until they go green, which is how a real failure gets ignored.
ltms added this to the 1.1 — single-host close-out milestone 2026-08-16 17:52:10 +02:00
ltms commented 2026-08-16 17:54:32 +02:00
Author
Owner
Copy Link
Copy Source

Update: I have now reproduced it myself, and two more independent observations came in. The ticket said I could not reproduce it. That is no longer true, and the correction matters — it removes the last reason to think this is specific to one worker's environment.

My own run, building PR #94 (CB-598, which touches only ReplyPushLoop):

[INFO] Running dev.ltms.bridged.msg.ReplyPushLoopTest
[INFO] Tests run: 43, Failures: 0, Errors: 0, Skipped: 0
[INFO] Running dev.ltms.bridged.msg.AmqpReplyInboxRecoveryRaceTest
[ERROR] Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 3.925 s <<< FAILURE!
[ERROR] ...recoverySweepDoesNotFailAPublishThatRegistersWhileItIsRunning -- Time elapsed: 3.686 s
org.opentest4j.AssertionFailedError: a publish that registered while the recovery sweep was running
must not be failed by it, but got: java.lang.IllegalStateException: AMQP connection recovered
mid-publish; confirm status of reply fresh is unknown

Same test, same assertion, same message, 3.7s against a 30s timeout. BUILD FAILURE on a PR whose diff does not touch AMQP code at all.

Separately, the CB-598 implementer hit it during its own work and characterised it without being asked: it reran the class alone three times with no code changes in between and got one failure and two passes. That is the clearest statement of the problem — the same bytes produce different results.

So the observed rate across four independent observers is: 3/3 fail, 1/3 fail, 0/3 fail (me, idle), 1/1 fail (me, loaded). Load correlates, but nothing here is deterministic.

Two things follow.

The diagnosis holds and gets stronger. A test whose outcome changes with no code change cannot be reporting a real defect in AmqpReplyInbox. Combined with the reading of the interleaving in the ticket above, it is the test that is wrong.

The cost is already being paid. This has now consumed time from three separate pieces of unrelated work — a documentation ticket, a nudge-loop ticket, and my own merge verification. Each one had to stop and prove the failure was not theirs. That is the real argument for treating it as a release blocker rather than an annoyance.

I am holding the merge of #94 until this lands, so main is not knowingly merged onto while red.

**Update: I have now reproduced it myself, and two more independent observations came in.** The ticket said I could not reproduce it. That is no longer true, and the correction matters — it removes the last reason to think this is specific to one worker's environment. My own run, building PR #94 (CB-598, which touches only `ReplyPushLoop`): ``` [INFO] Running dev.ltms.bridged.msg.ReplyPushLoopTest [INFO] Tests run: 43, Failures: 0, Errors: 0, Skipped: 0 [INFO] Running dev.ltms.bridged.msg.AmqpReplyInboxRecoveryRaceTest [ERROR] Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 3.925 s <<< FAILURE! [ERROR] ...recoverySweepDoesNotFailAPublishThatRegistersWhileItIsRunning -- Time elapsed: 3.686 s org.opentest4j.AssertionFailedError: a publish that registered while the recovery sweep was running must not be failed by it, but got: java.lang.IllegalStateException: AMQP connection recovered mid-publish; confirm status of reply fresh is unknown ``` Same test, same assertion, same message, 3.7s against a 30s timeout. `BUILD FAILURE` on a PR whose diff does not touch AMQP code at all. Separately, the CB-598 implementer hit it during its own work and characterised it without being asked: it reran the class alone three times with no code changes in between and got **one failure and two passes**. That is the clearest statement of the problem — the same bytes produce different results. So the observed rate across four independent observers is: 3/3 fail, 1/3 fail, 0/3 fail (me, idle), 1/1 fail (me, loaded). Load correlates, but nothing here is deterministic. Two things follow. **The diagnosis holds and gets stronger.** A test whose outcome changes with no code change cannot be reporting a real defect in `AmqpReplyInbox`. Combined with the reading of the interleaving in the ticket above, it is the test that is wrong. **The cost is already being paid.** This has now consumed time from three separate pieces of unrelated work — a documentation ticket, a nudge-loop ticket, and my own merge verification. Each one had to stop and prove the failure was not theirs. That is the real argument for treating it as a release blocker rather than an annoyance. I am holding the merge of #94 until this lands, so `main` is not knowingly merged onto while red.
ltms closed this issue 2026-08-16 18:08:24 +02:00
ltms commented 2026-08-16 18:08:38 +02:00
Author
Owner
Copy Link
Copy Source

Merged as a36b7cc (PR #97). Test file only — the production synchronized (publishChannelLock) guard is unchanged.

The Thread.sleep(5) head start is replaced by a CountDownLatch that the first stale publish thread counts down when it sees its own failure. That failure can only come from inside failPendingPublishesOnRecovery(), which holds the lock for its whole loop, so the latch is proof the sweep is running and holding the lock. fresh starts only after that. Case 2 is now impossible by construction, and the comment at the call site says so. STALE_PUBLISHES dropped from 100,000 to 2,000; the class runs in about 0.6s instead of 4.4s.

I checked all six criteria myself, not from the report:

  • No sleep decides the lock — read the diff. The two remaining sleeps are a poll interval and an unrelated close() test.
  • Still catches the bug — I replaced the guard with if (true) and ran it 5 times: 5/5 AssertionFailedError, the exact message from this issue. Restored, tree clean.
  • Passes under load — 10 consecutive runs in one worktree while a full mvn clean install ran in another: 10/10 pass.
  • No production change — git diff main...branch is one file, 37 insertions.
  • Build — Tests run: 822, Failures: 0, Errors: 0, Skipped: 0, BUILD SUCCESS, run unpiped.

main is green again, so the hold on #94 is lifted.

Merged as a36b7cc (PR #97). Test file only — the production `synchronized (publishChannelLock)` guard is unchanged. The `Thread.sleep(5)` head start is replaced by a `CountDownLatch` that the first stale publish thread counts down when it sees its own failure. That failure can only come from inside `failPendingPublishesOnRecovery()`, which holds the lock for its whole loop, so the latch is proof the sweep is running and holding the lock. `fresh` starts only after that. Case 2 is now impossible by construction, and the comment at the call site says so. `STALE_PUBLISHES` dropped from 100,000 to 2,000; the class runs in about 0.6s instead of 4.4s. I checked all six criteria myself, not from the report: - **No sleep decides the lock** — read the diff. The two remaining sleeps are a poll interval and an unrelated `close()` test. - **Still catches the bug** — I replaced the guard with `if (true)` and ran it 5 times: 5/5 `AssertionFailedError`, the exact message from this issue. Restored, tree clean. - **Passes under load** — 10 consecutive runs in one worktree while a full `mvn clean install` ran in another: 10/10 pass. - **No production change** — `git diff main...branch` is one file, 37 insertions. - **Build** — `Tests run: 822, Failures: 0, Errors: 0, Skipped: 0`, `BUILD SUCCESS`, run unpiped. `main` is green again, so the hold on #94 is lifted.
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 1.1 — single-host close-out
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#95
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?