Every async ticket dies at a hardcoded 30 minutes, so any unit longer than that always reports failed while the member is still working — 41 measured at exactly 1800s #588

Open
opened 2026-09-12 16:40:37 +02:00 by ltms · 1 comment
Owner

What happens

fleet_send{wait:false} returns a ticket. That ticket is given a fixed 30-minute deadline, and
nothing about the brief, the unit, or the member can change it.

fleetd/src/main/java/dev/ltms/fleet/msg/MessageService.java:56

private static final long ASYNC_TIMEOUT_MS = 30 * 60 * 1_000L;

It is passed straight to send() on the async route, at :1314:

Reply result = send(target, content, ASYNC_TIMEOUT_MS, onAccepted, task);

When it fires, send() checks whether the text had reached the pane and reports
TIMED_OUT_WORKING if it had (:992-999):

log.debug("send to {} timed out (delivered={})", target, wasDelivered);
Outcome outcome;
if (wasDelivered) {
    outcome = Outcome.TIMED_OUT_WORKING;

The lead sees fleet_poll{ticket} → [failed — no reply — timed_out_working].

There is no config knob for it. Grepping fleetd/fleetd.example.yaml for timeout keys returns
only spawnReadyTimeoutMs / spawnReadyPollMs and drainTimeoutSeconds. (This is a different
constant from TICKET_TTL_NANOS at :63, the 10-minute post-completion retention that #197
changed to run from completion. That one is fine. This one is the deadline for the work itself.)

The measurement

Today two workers were delegated a mutation sweep over Fleetd.java (#587), split into two parts.
Both tickets reported failed. The daemon log:

21:02:03.612 DEBUG d.l.fleet.msg.MessageService - async send task-1 -> term_65b49a264820f21c
21:02:30.840 DEBUG d.l.fleet.msg.MessageService - async send task-2 -> term_65b49a317a46221d
21:32:03.854 DEBUG d.l.fleet.msg.MessageService - send to term_65b49a264820f21c timed out (delivered=true)
21:32:31.133 DEBUG d.l.fleet.msg.MessageService - send to term_65b49a317a46221d timed out (delivered=true)

1800.2 s and 1800.3 s. delivered=true on both — the brief had landed.

At 21:37, five minutes after both tickets were declared failed, fleet_list reported both members
state: busy, liveStatus: working, idleForSeconds: null, and one of the two worktrees had
written a surefire report one second before I looked. Both were doing exactly the work they
were asked to do.

This is not a one-off. Pairing every async send task-N -> <target> line in fleetd/fleetd.out
with the later send to <target> timed out line for the same target:

count
timed out (delivered=…) lines in the log 58
pairable with their own send line 50 (8 unpairable — the send had rotated out of the log)
elapsed 1800 ± 1 s 41
of those 41, delivered=true 30
any other elapsed 9

41 of 50 land on the constant, across several weeks and many different member sessions.

Reproduce with:

python3 - <<'PY'
import re
sends, rows = {}, []
for ln in open('fleetd/fleetd.out', errors='replace'):
    m = re.match(r'^(\d\d:\d\d:\d\d\.\d+).*async send (task-\d+) -> (\S+)', ln)
    if m: sends.setdefault(m.group(3), []).append((m.group(1), m.group(2)))
    m = re.match(r'^(\d\d:\d\d:\d\d\.\d+).*send to (\S+) timed out \(delivered=(\w+)\)', ln)
    if m: rows.append((m.group(1), m.group(2), m.group(3)))
def t(s):
    h, mi, r = s.split(':'); return int(h)*3600+int(mi)*60+float(r)
for ts, tgt, d in rows:
    c = [st for st, _ in sends.get(tgt, []) if t(st) < t(ts)]
    if c: print("%-20s %8.1f s  delivered=%s" % (tgt[-18:], t(ts)-t(c[-1]), d))
PY

Why this matters

The ticket has a budget the brief does not know about. A unit that runs longer than 30 minutes
always loses its ticket, however healthy the member is. Three costs follow:

  1. TIMED_OUT_WORKING carries no information about the member. delivered=true says the text
    landed. The outcome is a fact about a clock, and it is named as though it were a fact about a
    worker. A lead reading "failed" reasonably concludes the unit is lost, and the natural next move
    — write the work off, or re-send the brief — is wrong in both directions. Re-sending is worse
    than wrong: a second send to a busy member is accepted and never delivered.
  2. A whole class of unit cannot use the ticket channel at all. Any brief that runs one Maven
    build per mutation site is structurally over 30 minutes here; the full contract suite alone is
    1825 tests. So the channel the orchestration procedure is built around is only usable for units
    under half an hour, and nothing says so.
  3. Recovery is undocumented and non-obvious. The report is not lost — the member's
    fleet_reply still lands in its inbox, which has a different lifetime — but it can only be
    collected with fleet_poll{target}, not fleet_poll{ticket}. Nothing in the outcome text, the
    tool description, or CLAUDE.md points at that.

What I did not measure

  • I have not checked what the 9 non-1800 s rows are. Some have delivered=false, so they are a
    different path (never delivered), not this one.
  • I have not checked whether any test pins ASYNC_TIMEOUT_MS or the TIMED_OUT_WORKING branch at
    :992-999. Worth doing before changing it — if the constant has no test, changing it is
    invisible to the suite.

What would fix it

Roughly in order of value, not a prescription:

  1. Make the deadline configurable, and settable per send. A sweep and a one-line review do not
    belong on the same clock. A fleet_send parameter is the honest place, since the caller is the
    only party that knows how long the unit should take.
  2. Say what the outcome actually means. TIMED_OUT_WORKING should tell the lead the deadline
    elapsed, name the deadline, and name fleet_poll{target} as the way to collect the report. Right
    now [failed — no reply — timed_out_working] reads as a dead worker.
  3. Do not call it failed. The push-loop hook computes failed = … || !reply.completed()
    (:1297-1299), so a still-working member's ticket is pushed to the lead as a failure. A third
    state — the unit is still running, the ticket is closed — is the accurate answer. This is the
    same shape as #497: one symbol covering two states that need opposite handling.

Same shape as #466 (a flat 30 minutes chosen for one distribution and applied to all of them);
adjacent to #530 and #410, which are also about a lead being told something confident about a
member that the daemon did not actually check.

## What happens `fleet_send{wait:false}` returns a ticket. That ticket is given a **fixed 30-minute deadline**, and nothing about the brief, the unit, or the member can change it. `fleetd/src/main/java/dev/ltms/fleet/msg/MessageService.java:56` ```java private static final long ASYNC_TIMEOUT_MS = 30 * 60 * 1_000L; ``` It is passed straight to `send()` on the async route, at `:1314`: ```java Reply result = send(target, content, ASYNC_TIMEOUT_MS, onAccepted, task); ``` When it fires, `send()` checks whether the text had reached the pane and reports `TIMED_OUT_WORKING` if it had (`:992-999`): ```java log.debug("send to {} timed out (delivered={})", target, wasDelivered); Outcome outcome; if (wasDelivered) { outcome = Outcome.TIMED_OUT_WORKING; ``` The lead sees `fleet_poll{ticket}` → `[failed — no reply — timed_out_working]`. **There is no config knob for it.** Grepping `fleetd/fleetd.example.yaml` for timeout keys returns only `spawnReadyTimeoutMs` / `spawnReadyPollMs` and `drainTimeoutSeconds`. (This is a different constant from `TICKET_TTL_NANOS` at `:63`, the 10-minute *post-completion* retention that #197 changed to run from completion. That one is fine. This one is the deadline for the work itself.) ## The measurement Today two workers were delegated a mutation sweep over `Fleetd.java` (#587), split into two parts. Both tickets reported failed. The daemon log: ``` 21:02:03.612 DEBUG d.l.fleet.msg.MessageService - async send task-1 -> term_65b49a264820f21c 21:02:30.840 DEBUG d.l.fleet.msg.MessageService - async send task-2 -> term_65b49a317a46221d 21:32:03.854 DEBUG d.l.fleet.msg.MessageService - send to term_65b49a264820f21c timed out (delivered=true) 21:32:31.133 DEBUG d.l.fleet.msg.MessageService - send to term_65b49a317a46221d timed out (delivered=true) ``` 1800.2 s and 1800.3 s. `delivered=true` on both — the brief had landed. At 21:37, five minutes after both tickets were declared failed, `fleet_list` reported both members `state: busy`, `liveStatus: working`, `idleForSeconds: null`, and one of the two worktrees had written a surefire report **one second** before I looked. Both were doing exactly the work they were asked to do. This is not a one-off. Pairing every `async send task-N -> <target>` line in `fleetd/fleetd.out` with the later `send to <target> timed out` line for the same target: | | count | |---|---| | `timed out (delivered=…)` lines in the log | 58 | | pairable with their own send line | 50 (8 unpairable — the send had rotated out of the log) | | **elapsed 1800 ± 1 s** | **41** | | of those 41, `delivered=true` | 30 | | any other elapsed | 9 | 41 of 50 land on the constant, across several weeks and many different member sessions. Reproduce with: ```bash python3 - <<'PY' import re sends, rows = {}, [] for ln in open('fleetd/fleetd.out', errors='replace'): m = re.match(r'^(\d\d:\d\d:\d\d\.\d+).*async send (task-\d+) -> (\S+)', ln) if m: sends.setdefault(m.group(3), []).append((m.group(1), m.group(2))) m = re.match(r'^(\d\d:\d\d:\d\d\.\d+).*send to (\S+) timed out \(delivered=(\w+)\)', ln) if m: rows.append((m.group(1), m.group(2), m.group(3))) def t(s): h, mi, r = s.split(':'); return int(h)*3600+int(mi)*60+float(r) for ts, tgt, d in rows: c = [st for st, _ in sends.get(tgt, []) if t(st) < t(ts)] if c: print("%-20s %8.1f s delivered=%s" % (tgt[-18:], t(ts)-t(c[-1]), d)) PY ``` ## Why this matters **The ticket has a budget the brief does not know about.** A unit that runs longer than 30 minutes *always* loses its ticket, however healthy the member is. Three costs follow: 1. **`TIMED_OUT_WORKING` carries no information about the member.** `delivered=true` says the text landed. The outcome is a fact about a clock, and it is named as though it were a fact about a worker. A lead reading "failed" reasonably concludes the unit is lost, and the natural next move — write the work off, or re-send the brief — is wrong in both directions. Re-sending is worse than wrong: a second send to a busy member is accepted and never delivered. 2. **A whole class of unit cannot use the ticket channel at all.** Any brief that runs one Maven build per mutation site is structurally over 30 minutes here; the full contract suite alone is 1825 tests. So the channel the orchestration procedure is built around is only usable for units under half an hour, and nothing says so. 3. **Recovery is undocumented and non-obvious.** The report is not lost — the member's `fleet_reply` still lands in its inbox, which has a different lifetime — but it can only be collected with `fleet_poll{target}`, not `fleet_poll{ticket}`. Nothing in the outcome text, the tool description, or `CLAUDE.md` points at that. ## What I did not measure - I have not checked what the 9 non-1800 s rows are. Some have `delivered=false`, so they are a different path (never delivered), not this one. - I have not checked whether any test pins `ASYNC_TIMEOUT_MS` or the `TIMED_OUT_WORKING` branch at `:992-999`. Worth doing before changing it — if the constant has no test, changing it is invisible to the suite. ## What would fix it Roughly in order of value, not a prescription: 1. **Make the deadline configurable**, and settable per send. A sweep and a one-line review do not belong on the same clock. A `fleet_send` parameter is the honest place, since the caller is the only party that knows how long the unit should take. 2. **Say what the outcome actually means.** `TIMED_OUT_WORKING` should tell the lead the deadline elapsed, name the deadline, and name `fleet_poll{target}` as the way to collect the report. Right now `[failed — no reply — timed_out_working]` reads as a dead worker. 3. **Do not call it `failed`.** The push-loop hook computes `failed = … || !reply.completed()` (`:1297-1299`), so a still-working member's ticket is pushed to the lead as a failure. A third state — the unit is still running, the ticket is closed — is the accurate answer. This is the same shape as #497: one symbol covering two states that need opposite handling. Same shape as #466 (a flat 30 minutes chosen for one distribution and applied to all of them); adjacent to #530 and #410, which are also about a lead being told something confident about a member that the daemon did not actually check.
Author
Owner

Closing the second "what I did not measure" bullet: nothing pins ASYNC_TIMEOUT_MS, and the
coverage that looks like it does comes in through a different door.

$ grep -rn 'ASYNC_TIMEOUT_MS' fleetd/src/test/java --include='*.java' | wc -l
0
$ grep -rn 'ASYNC_TIMEOUT_MS' fleetd/src/main/java --include='*.java'
MessageService.java:56    private static final long ASYNC_TIMEOUT_MS = 30 * 60 * 1_000L;
MessageService.java:668   * {@link #ASYNC_TIMEOUT_MS} — thirty minutes — even though the worker ...
MessageService.java:693   * to {@link #ASYNC_TIMEOUT_MS}, exactly as {@code abandonFails...}
MessageService.java:1314  Reply result = send(target, content, ASYNC_TIMEOUT_MS, onAccepted, task);
$ grep -rn '1800000\|1_800_000\|30 \* 60' fleetd/src/test/java --include='*.java' | wc -l
0

One declaration, two javadoc mentions, one use. No test names it and no test asserts its value.

The coverage that looks like it covers this

TIMED_OUT_WORKING has 11 assertions in MessageServiceTest. That reads like a well-pinned
branch. Every one of them arrives through a send(...) or answer(...) call carrying its own
short explicit timeout
, never through the async route's constant. For example
aReplyAfterAnswerTimesOutStillCompletesTheAsyncTicket:1334 does start with the real
messages.sendAsync(T, …), and its TIMED_OUT_WORKING assertion at :1347 is about a different
call entirely:

MessageService.Reply answerReply = messages.answer(asking.turnId(), "config.yaml", 150);
assertEquals(MessageService.Outcome.TIMED_OUT_WORKING, answerReply.outcome(),
        "the primary's own bounded wait gives up before the worker finishes resuming");

150 ms, passed in by the test. Three tests mention both messages.sendAsync and
TIMED_OUT_WORKING (:1334, :1365, :1571) and in all three the outcome comes from answer's
bounded wait, not from sendAsync's deadline.

So the outcome is covered and the deadline is not. No test reaches :992-999 by way of
ASYNC_TIMEOUT_MS, and none can, because doing so means waiting thirty minutes. This is the
#561/#575 shape again: an invariant maintained at a
site nobody instantiates, with a healthy non-zero assertion total sitting in front of it.

A counting trap for whoever picks this up

grep -c 'sendAsync(' fleetd/src/test/java returns 86, and that number is meaningless.
MessageServiceTest has a private helper of its own called sendAsync, at :64-70:

private CompletableFuture<MessageService.Reply> sendAsync(String content) {
    return CompletableFuture.supplyAsync(() -> messages.send(T, content, 5000));
}

That is the blocking send with a 5-second timeout on a background thread — not the production
async route at all. Counted apart: 25 calls to the helper, 38 to the real messages.sendAsync. I
made this mistake first and am recording it so the next reader does not: two different things share
one name inside a single file, so the name records neither.

What I have not run

I have not run a build with the constant changed, so I am not claiming a measured "mutate it
and the suite stays green". What the greps above do support is narrower and still enough: no
assertion can observe the value, because nothing reads it. Raising it is therefore invisible to
the suite. Lowering it is not symmetric — a value below a test's own duration could start failing
tests that drive the real sendAsync and expect a reply, so a mutation proof here should raise the
constant, not lower it. (I am deferring that build because two workers are mid-build in their own
worktrees right now, and concurrent Maven builds in this tree hang each other.)

What this adds to the fix

Item 1 above (make the deadline configurable) now needs a wiring test, not just a knob — otherwise
the knob can be added and silently not wired, which is the same defect one layer up. The shape to
copy is FleetdLoopHealthSourceWiringTest, added in #584 for exactly this reason: extract the
deadline to a named seam, then assert that the async route asks that seam rather than a constant.
That test is RED today, which item 1 on its own would not be.

Closing the second "what I did not measure" bullet: **nothing pins `ASYNC_TIMEOUT_MS`, and the coverage that looks like it does comes in through a different door.** ``` $ grep -rn 'ASYNC_TIMEOUT_MS' fleetd/src/test/java --include='*.java' | wc -l 0 $ grep -rn 'ASYNC_TIMEOUT_MS' fleetd/src/main/java --include='*.java' MessageService.java:56 private static final long ASYNC_TIMEOUT_MS = 30 * 60 * 1_000L; MessageService.java:668 * {@link #ASYNC_TIMEOUT_MS} — thirty minutes — even though the worker ... MessageService.java:693 * to {@link #ASYNC_TIMEOUT_MS}, exactly as {@code abandonFails...} MessageService.java:1314 Reply result = send(target, content, ASYNC_TIMEOUT_MS, onAccepted, task); $ grep -rn '1800000\|1_800_000\|30 \* 60' fleetd/src/test/java --include='*.java' | wc -l 0 ``` One declaration, two javadoc mentions, one use. No test names it and no test asserts its value. ### The coverage that looks like it covers this `TIMED_OUT_WORKING` has **11 assertions** in `MessageServiceTest`. That reads like a well-pinned branch. Every one of them arrives through a `send(...)` or `answer(...)` call carrying its **own short explicit timeout**, never through the async route's constant. For example `aReplyAfterAnswerTimesOutStillCompletesTheAsyncTicket:1334` does start with the real `messages.sendAsync(T, …)`, and its `TIMED_OUT_WORKING` assertion at `:1347` is about a different call entirely: ```java MessageService.Reply answerReply = messages.answer(asking.turnId(), "config.yaml", 150); assertEquals(MessageService.Outcome.TIMED_OUT_WORKING, answerReply.outcome(), "the primary's own bounded wait gives up before the worker finishes resuming"); ``` 150 ms, passed in by the test. Three tests mention both `messages.sendAsync` and `TIMED_OUT_WORKING` (`:1334`, `:1365`, `:1571`) and in all three the outcome comes from `answer`'s bounded wait, not from `sendAsync`'s deadline. **So the outcome is covered and the deadline is not.** No test reaches `:992-999` *by way of* `ASYNC_TIMEOUT_MS`, and none can, because doing so means waiting thirty minutes. This is the [#561](https://git.ltms.dev/fleet/fleetd/issues/561)/#575 shape again: an invariant maintained at a site nobody instantiates, with a healthy non-zero assertion total sitting in front of it. ### A counting trap for whoever picks this up `grep -c 'sendAsync(' fleetd/src/test/java` returns **86**, and that number is meaningless. `MessageServiceTest` has a *private helper of its own* called `sendAsync`, at `:64-70`: ```java private CompletableFuture<MessageService.Reply> sendAsync(String content) { return CompletableFuture.supplyAsync(() -> messages.send(T, content, 5000)); } ``` That is the **blocking** `send` with a 5-second timeout on a background thread — not the production async route at all. Counted apart: 25 calls to the helper, 38 to the real `messages.sendAsync`. I made this mistake first and am recording it so the next reader does not: two different things share one name inside a single file, so the name records neither. ### What I have not run I have **not** run a build with the constant changed, so I am not claiming a measured "mutate it and the suite stays green". What the greps above do support is narrower and still enough: no assertion can observe the *value*, because nothing reads it. Raising it is therefore invisible to the suite. Lowering it is not symmetric — a value below a test's own duration could start failing tests that drive the real `sendAsync` and expect a reply, so a mutation proof here should raise the constant, not lower it. (I am deferring that build because two workers are mid-build in their own worktrees right now, and concurrent Maven builds in this tree hang each other.) ### What this adds to the fix Item 1 above (make the deadline configurable) now needs a wiring test, not just a knob — otherwise the knob can be added and silently not wired, which is the same defect one layer up. The shape to copy is `FleetdLoopHealthSourceWiringTest`, added in #584 for exactly this reason: extract the deadline to a named seam, then assert that the async route asks *that* seam rather than a constant. That test is RED today, which item 1 on its own would not be.
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: fleet/fleetd#588