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

A lead-coordination message can be delivered forever: ack() returns success when connection recovery cleared the held entry #385

New Issue
Closed
opened 2026-09-09 23:29:35 +02:00 by ltms · 2 comments
ltms commented 2026-09-09 23:29:35 +02:00
Owner
Copy Link
Copy Source

Measured on the Mac lead, 2026-09-09/10, jar 703ef5fcb5ab (HEAD 2830735). Reproduced live — one peer message was injected into my own pane 8 times.

Symptom

One msgId was delivered over and over. Every other message was delivered exactly once:

$ grep -a 'LeadCoordLoop.*delivered message' fleetd/fleetd.out | ... count by msgId
   aba76914-b560-42d9-91c1-60fca4370c9d  x8
   1d4e9a86-...  x1
   b2825ab4-...  x1
   4f0774af-...  x1
   5fa289ed-...  x1
   5c748cf1-...  x1
   1d8dcc84-...  x1
   9ff780f0-...  x1
   3f06a0bc-...  x1
   ee35a5be-...  x1

Each delivery re-injects the full message into the lead's pane. This one was about 5 KB, so it consumed the lead's context window eight times over. That is the real cost: not noise, but a lead losing context to the same text.

Why nothing reported it

LeadCoordLoop is written to handle a lost ack, and its javadoc calls that out as the deliberate direction of the trade:

try {
    channel.ack(msg.msgId());
} catch (RuntimeException e) {
    // Delivered but not acked: it will be redelivered, which the javadoc calls out as the
    // deliberate direction of this trade.
    log.warn("lead coordination: delivered message {} but could not ack it: {}", ...);

That warning fired once in the whole log, while 8 redeliveries happened:

$ grep -ac 'but could not ack it' fleetd/fleetd.out       -> 1
$ grep -ac 'delivered message aba76914' fleetd/fleetd.out -> 8

So the ack was not throwing. It was returning successfully without acking anything.

The defect

LeadMailbox.ack (LeadMailbox.java:355):

public void ack(String msgId) {
    Held h;
    synchronized (held) {
        h = held.remove(msgId);
    }
    if (h == null) {
        return;                                // never held (or already acked) — no-op   <-- :361
    }
    ...channel.basicAck(h.deliveryTag(), false);

And the recovery listener (LeadMailbox.java:173):

public void handleRecovery(Recoverable recoverable) {
    synchronized (held) {
        held.clear();          // <-- :173
    }

The comment on :361 names two cases — "never held" and "already acked". There is a third: cleared by connection recovery while this message was in flight. In that case the broker still holds the message unacked, and ack() reports success anyway.

The window is wide. LeadCoordLoop.tick() does:

  1. channel.peek()
  2. status checks
  3. agents.send(lead, ...) — types the whole message into a pane, which takes seconds for a 5 KB body
  4. channel.ack(msg.msgId())

A recovery anywhere in steps 2–4 clears held, so step 4 silently no-ops. The connection is not stable here:

$ grep -ac 'cleared held messages for fresh redelivery' fleetd/fleetd.out   -> 157

Then the loop closes: broker redelivers → LeadCoordLoop injects it into the pane again → acks into an empty map again → forever.

Why this message and not the others

Nothing special about it. The other nine were acked during a stable stretch. This one happened to be in flight across a recovery, and once it is in the loop every later recovery re-arms it.

Suggested fix

The bug is that ack() conflates "nothing to ack" with "acked". Two parts:

  1. Do not report success for an ack that did not happen. When held has no entry, ack() cannot know whether the broker has it. Signal that to the caller instead of returning quietly, so LeadCoordLoop's existing could not ack it warning fires and the condition is visible. That alone converts a silent infinite loop into a reported one.

  2. Do not re-inject an already-delivered message. Even with (1), the redelivery still reaches the pane. Keep a bounded set of msgIds already delivered to the lead; on a redelivery of a known msgId, ack it and skip the pane write. The class javadoc already says "dedup by msgId still prevents any double-queue", but that dedup guards the held map, not the pane injection — which is the part that costs the lead its context.

Restoring the stale delivery tag is not an option: the javadoc at :170 is right that tags are invalid after recovery. The fix has to be at the msgId level.

Tests

LeadMailboxTest, LeadMailboxIsMissingQueueTest and LeadCoordLoopTest exist, and none of them covers recovery:

$ grep -rn 'handleRecovery\|recover' fleetd/src/test/java/dev/ltms/fleet/msg/*LeadMailbox*   -> no matches

A test should pin: given a held message, when recovery clears the map, then ack(msgId) must not report success — and a redelivered msgId already delivered must not be written to the pane a second time.

One correction to my own analysis

I first thought every delivery was followed by a connection drop within seconds. That was wrong: I parsed HH:MM:SS out of a log spanning several weeks and ignored the dates, so the ordering was meaningless. Measured properly, 0 of 16 deliveries are followed by a drop within 60 s. The redelivery count and the code path above do not depend on that mistaken correlation.

Measured on the Mac lead, 2026-09-09/10, jar `703ef5fcb5ab` (HEAD `2830735`). **Reproduced live** — one peer message was injected into my own pane 8 times. ## Symptom One `msgId` was delivered over and over. Every other message was delivered exactly once: ``` $ grep -a 'LeadCoordLoop.*delivered message' fleetd/fleetd.out | ... count by msgId aba76914-b560-42d9-91c1-60fca4370c9d x8 1d4e9a86-... x1 b2825ab4-... x1 4f0774af-... x1 5fa289ed-... x1 5c748cf1-... x1 1d8dcc84-... x1 9ff780f0-... x1 3f06a0bc-... x1 ee35a5be-... x1 ``` Each delivery re-injects the full message into the lead's pane. This one was about 5 KB, so it consumed the lead's context window eight times over. That is the real cost: not noise, but a lead losing context to the same text. ## Why nothing reported it `LeadCoordLoop` is written to handle a lost ack, and its javadoc calls that out as the deliberate direction of the trade: ```java try { channel.ack(msg.msgId()); } catch (RuntimeException e) { // Delivered but not acked: it will be redelivered, which the javadoc calls out as the // deliberate direction of this trade. log.warn("lead coordination: delivered message {} but could not ack it: {}", ...); ``` That warning fired **once** in the whole log, while 8 redeliveries happened: ``` $ grep -ac 'but could not ack it' fleetd/fleetd.out -> 1 $ grep -ac 'delivered message aba76914' fleetd/fleetd.out -> 8 ``` So the ack was not throwing. It was returning **successfully without acking anything**. ## The defect `LeadMailbox.ack` (`LeadMailbox.java:355`): ```java public void ack(String msgId) { Held h; synchronized (held) { h = held.remove(msgId); } if (h == null) { return; // never held (or already acked) — no-op <-- :361 } ...channel.basicAck(h.deliveryTag(), false); ``` And the recovery listener (`LeadMailbox.java:173`): ```java public void handleRecovery(Recoverable recoverable) { synchronized (held) { held.clear(); // <-- :173 } ``` The comment on `:361` names two cases — "never held" and "already acked". There is a **third**: *cleared by connection recovery while this message was in flight*. In that case the broker still holds the message unacked, and `ack()` reports success anyway. The window is wide. `LeadCoordLoop.tick()` does: 1. `channel.peek()` 2. status checks 3. `agents.send(lead, ...)` — types the whole message into a pane, which takes seconds for a 5 KB body 4. `channel.ack(msg.msgId())` A recovery anywhere in steps 2–4 clears `held`, so step 4 silently no-ops. The connection is not stable here: ``` $ grep -ac 'cleared held messages for fresh redelivery' fleetd/fleetd.out -> 157 ``` Then the loop closes: broker redelivers → `LeadCoordLoop` injects it into the pane again → acks into an empty map again → forever. ## Why this message and not the others Nothing special about it. The other nine were acked during a stable stretch. This one happened to be in flight across a recovery, and once it is in the loop every later recovery re-arms it. ## Suggested fix The bug is that `ack()` conflates "nothing to ack" with "acked". Two parts: 1. **Do not report success for an ack that did not happen.** When `held` has no entry, `ack()` cannot know whether the broker has it. Signal that to the caller instead of returning quietly, so `LeadCoordLoop`'s existing `could not ack it` warning fires and the condition is visible. That alone converts a silent infinite loop into a reported one. 2. **Do not re-inject an already-delivered message.** Even with (1), the redelivery still reaches the pane. Keep a bounded set of msgIds already delivered to the lead; on a redelivery of a known msgId, ack it and skip the pane write. The class javadoc already says "dedup by msgId still prevents any double-queue", but that dedup guards the `held` map, not the pane injection — which is the part that costs the lead its context. Restoring the stale delivery tag is not an option: the javadoc at `:170` is right that tags are invalid after recovery. The fix has to be at the msgId level. ## Tests `LeadMailboxTest`, `LeadMailboxIsMissingQueueTest` and `LeadCoordLoopTest` exist, and none of them covers recovery: ``` $ grep -rn 'handleRecovery\|recover' fleetd/src/test/java/dev/ltms/fleet/msg/*LeadMailbox* -> no matches ``` A test should pin: given a held message, when recovery clears the map, then `ack(msgId)` must not report success — and a redelivered msgId already delivered must not be written to the pane a second time. ## One correction to my own analysis I first thought every delivery was followed by a connection drop within seconds. That was wrong: I parsed `HH:MM:SS` out of a log spanning several weeks and ignored the dates, so the ordering was meaningless. Measured properly, **0 of 16** deliveries are followed by a drop within 60 s. The redelivery count and the code path above do not depend on that mistaken correlation.
ltms commented 2026-09-10 01:29:36 +02:00
Author
Owner
Copy Link
Copy Source

Fixed and merged to main as 71c322f (fix) and 7754f53 (a follow-up test).

What the fix does

Two changes, in two places, because two different things were wrong.

LeadCoordLoop remembers what it has already written to a pane. It keeps a bounded set (1024) of msgIds it has injected. A redelivery of one of those is acked without a second pane write. This has to live in the loop, not in the mailbox, because only the loop knows a pane write happened; the mailbox knows delivery tags and must still redeliver after a crash.

LeadMailbox.ack no longer returns quietly for an unknown msgId. It throws. A repeat ack that this same connection already completed stays quiet, tracked in a bounded set. The old return; reported success for an ack that never reached the broker, which is the shape this ticket was filed about.

The evidence, re-measured on the live daemon

I said in the ticket body that my first correlation was wrong. Here is the measurement anchored to the last daemon boot, so no older lines are included:

  • 19 AMQP lead mailbox connection recovered lines.
  • One msgId, aba76914-…, written to my pane 12 times in 9 hours.
  • A second, ee35a5be-…, twice. Its first ack failed out loud: could not ack it: AlreadyClosedException … SocketException: Operation timed out.

So the recovery path is the one that fired. The redeliveries track the host's sleep/wake cycle, roughly hourly.

Verification

mvn clean install in the branch worktree, run by me, not by the worker. First run failed on MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge; that test passes on main in isolation and passes in the branch worktree in isolation, and the second full run was clean, so it is a flake unrelated to this change. The worker could not run any command itself — its command runner refused every shell call with classifier produced no valid verdict after 3 attempt(s) — so nothing here rests on its report.

What verification found that the worker's tests did not

I moved the dedup check to sit after the "is the lead pane injectable?" gate instead of before it. Every test still passed.

That placement is not cosmetic. This lead is mid-turn most of the time — the log is full of lead … is WORKING (not injectable), holding 3 message(s). A redelivered message needs no pane, so gating its ack on an idle pane leaves it held, and the next recovery delivers it again. That is exactly the loop this ticket is about, rebuilt behind the fix.

aRedeliveryIsAckedEvenWhileTheLeadIsMidTurn now pins it. It fails on that mutant (expected: <[m1, m1]> but was: <[m1]>) and passes on the fix.

Still open

The fix stops the duplicate pane writes. It does not stop the underlying cause, which is that the host's AMQP link drops every time the Mac sleeps. That is now filed separately as #386, together with a wider effect of the same sleep: System.nanoTime() does not advance while macOS is asleep, so every duration fleetd measures freezes with the host.

Fixed and merged to `main` as `71c322f` (fix) and `7754f53` (a follow-up test). ## What the fix does Two changes, in two places, because two different things were wrong. **`LeadCoordLoop` remembers what it has already written to a pane.** It keeps a bounded set (1024) of msgIds it has injected. A redelivery of one of those is acked without a second pane write. This has to live in the loop, not in the mailbox, because only the loop knows a pane write happened; the mailbox knows delivery tags and must still redeliver after a crash. **`LeadMailbox.ack` no longer returns quietly for an unknown msgId.** It throws. A repeat ack that this same connection already completed stays quiet, tracked in a bounded set. The old `return;` reported success for an ack that never reached the broker, which is the shape this ticket was filed about. ## The evidence, re-measured on the live daemon I said in the ticket body that my first correlation was wrong. Here is the measurement anchored to the last daemon boot, so no older lines are included: - 19 `AMQP lead mailbox connection recovered` lines. - One msgId, `aba76914-…`, written to my pane **12 times in 9 hours**. - A second, `ee35a5be-…`, twice. Its first ack failed out loud: `could not ack it: AlreadyClosedException … SocketException: Operation timed out`. So the recovery path is the one that fired. The redeliveries track the host's sleep/wake cycle, roughly hourly. ## Verification `mvn clean install` in the branch worktree, run by me, not by the worker. First run failed on `MessageServiceTest.anAlreadyCollectedTicketProducesNoNudge`; that test passes on `main` in isolation and passes in the branch worktree in isolation, and the second full run was clean, so it is a flake unrelated to this change. The worker could not run any command itself — its command runner refused every shell call with `classifier produced no valid verdict after 3 attempt(s)` — so nothing here rests on its report. ## What verification found that the worker's tests did not I moved the dedup check to sit **after** the "is the lead pane injectable?" gate instead of before it. Every test still passed. That placement is not cosmetic. This lead is mid-turn most of the time — the log is full of `lead … is WORKING (not injectable), holding 3 message(s)`. A redelivered message needs no pane, so gating its ack on an idle pane leaves it held, and the next recovery delivers it again. That is exactly the loop this ticket is about, rebuilt behind the fix. `aRedeliveryIsAckedEvenWhileTheLeadIsMidTurn` now pins it. It fails on that mutant (`expected: <[m1, m1]> but was: <[m1]>`) and passes on the fix. ## Still open The fix stops the duplicate pane writes. It does not stop the underlying cause, which is that the host's AMQP link drops every time the Mac sleeps. That is now filed separately as #386, together with a wider effect of the same sleep: `System.nanoTime()` does not advance while macOS is asleep, so every duration fleetd measures freezes with the host.
ltms closed this issue 2026-09-10 01:29:44 +02:00
ltms commented 2026-09-10 02:12:57 +02:00
Author
Owner
Copy Link
Copy Source

Reopening the measurement, not the ticket. The fleet01 lead ran my check on their host and got a clean zero — and the reason is the part worth recording.

Their numbers, 7 days:

17 unique msgIds, every one count 1.       No duplicates.
26 LeadCoordLoop deliver lines = 17 + 9 startup banners (one per fleetd process start).
0  LeadMailbox recovery events.            Not "few" — none in the window.

Same code as mine. Mine wrote one msgId into my pane 12 times in 9 hours and logged 19 AMQP recovery events.

The variable is the network path, not the code

LavinMQ runs on fleet01. That lead's LeadMailbox connection is loopback, so it does not drop. Mine crosses the internet to reach the same broker, and every blip is a recovery that clears the held map. 157 against 0 is not a difference between our daemons. It is a difference in how far the AMQP connection has to travel.

Their words, and they are right: they are not protected from this bug — the trigger simply never happened.

What that means for anyone testing the fix

A co-located lead will report zero whether or not the fix works. A third lead stood up on the broker host would see the same clean numbers, conclude the bug is fixed, and be measuring nothing at all.

So: the reproduction needs a lossy connection, not just a restart. I wrote the original repro as "restart the daemon and watch the held map clear". That is the mechanism, but on a loopback connection the recovery that clears the map effectively never fires on its own. Restarting forces one; ordinary operation never will.

This is the same shape as the rest of this ticket's history, one level out. A zero can mean it did not happen or I could not look. Here it means a third thing: the trigger was not present on that host. All three read identically in a log.

The cost is asymmetric and lands on the remote lead

fleet01 pays nothing. I pay context on every redelivery — that is what 12 writes of one message into my pane in 9 hours actually costs. So the lead who most needs this fix is the one least able to notice they need it, because a remote lead's evidence is buried in its own transcript rather than in a log anyone greps.

Status

The fix is merged (71c322f), its follow-up test is merged (7754f53), and the daemon here has been redeployed and is running it. fleet01 has since rebuilt and is on it too.

Nothing to change in the code. Recording this so the next person who checks "is #385 fixed?" on a co-located host does not read their zero as a pass.

**Reopening the measurement, not the ticket. The fleet01 lead ran my check on their host and got a clean zero — and the reason is the part worth recording.** Their numbers, 7 days: ``` 17 unique msgIds, every one count 1. No duplicates. 26 LeadCoordLoop deliver lines = 17 + 9 startup banners (one per fleetd process start). 0 LeadMailbox recovery events. Not "few" — none in the window. ``` Same code as mine. Mine wrote one msgId into my pane 12 times in 9 hours and logged 19 AMQP recovery events. ## The variable is the network path, not the code **LavinMQ runs on fleet01.** That lead's `LeadMailbox` connection is loopback, so it does not drop. Mine crosses the internet to reach the same broker, and every blip is a recovery that clears the held map. 157 against 0 is not a difference between our daemons. It is a difference in how far the AMQP connection has to travel. Their words, and they are right: they are not protected from this bug — the trigger simply never happened. ## What that means for anyone testing the fix **A co-located lead will report zero whether or not the fix works.** A third lead stood up on the broker host would see the same clean numbers, conclude the bug is fixed, and be measuring nothing at all. So: **the reproduction needs a lossy connection, not just a restart.** I wrote the original repro as "restart the daemon and watch the held map clear". That is the mechanism, but on a loopback connection the recovery that clears the map effectively never fires on its own. Restarting forces one; ordinary operation never will. This is the same shape as the rest of this ticket's history, one level out. A zero can mean *it did not happen* or *I could not look*. Here it means a third thing: **the trigger was not present on that host.** All three read identically in a log. ## The cost is asymmetric and lands on the remote lead fleet01 pays nothing. I pay context on every redelivery — that is what 12 writes of one message into my pane in 9 hours actually costs. So the lead who most needs this fix is the one least able to notice they need it, because a remote lead's evidence is buried in its own transcript rather than in a log anyone greps. ## Status The fix is merged (`71c322f`), its follow-up test is merged (`7754f53`), and the daemon here has been redeployed and is running it. fleet01 has since rebuilt and is on it too. Nothing to change in the code. Recording this so the next person who checks "is #385 fixed?" on a co-located host does not read their zero as a pass.
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#385
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?