Skip to content

Bound the presence read, and let the drain alone decide delivery (#311, #304) - #316

Merged
scgopi merged 6 commits into
mainfrom
fix/311-drain-order-timeout
Sep 7, 2026
Merged

scgopi merged 6 commits into
mainfrom
fix/311-drain-order-timeout

Conversation

@scgopi

@scgopi scgopi commented Sep 7, 2026

Copy link
Copy Markdown
Owner

Four defects on one seam — how a staged follow-up decides when to be delivered — with a test each. A combined test that passes says nothing about which half works, so each defect below names the test that fails without its change and passes with it.

1. The presence read had no deadline — the blocker (#311)

onReadPresencePTYProcessSession.waitCollectingOutput ends only when the probe's terminationHandler closes the stream, and ssh's ConnectTimeout=10 bounds the connect, never a command left hanging on a host that has gone away (RemoteEnsureGate documents the same wedge from the other side). One such read held isDrainingFollowUps for the life of the daemon, so staged delivery stopped for every loop in the project — and a frozen queue reports exactly what an empty one reports, which is the property that let #304 and #306 go unnoticed.

Every reading in GraphStore now goes through one bounded presenceReading(of:) (Deadline.swift, 45s — longer than a healthy remote probe's three attempts at ConnectTimeout=10 with 1s and 2s of backoff). A read that runs out of time is .unknown, never a state: the distinction #286 established when a zmx probe that could not run was being read as .absent. An unknown target keeps its message queued and retried — not delivered blindly, not busy for ever.

The loser is abandoned rather than cancelled-and-awaited, because a structured withTaskGroup race waits for every child and would inherit the hang it is meant to bound.

Bounding it once also covers refreshPresence (a hang there wedges the poll itself) and sessionPermitsResolution, which asks a remote host whether a loop is still alive before resolving it irreversibly.

Test: aHungPresenceReadDoesNotStopDeliveryToOtherLoops — what it measures is not that the wedged loop recovers but that its neighbour is not taken down with it. On main the pass takes 10.05s and the neighbour waits behind the wedge; here it is 0.4s, the neighbour is served, and the wedged loop's message is still owed and delivered once its session answers again.

2. Two readings decided one question (#311)

deliversLater consulted the cached node.presence the poll writes once every 15s while the drain took a live reading — and delivering an item is itself what makes the target busy, so after the first delivery of a tick the two are not occasionally in disagreement, they are guaranteed to disagree for the rest of it. deliversLater no longer reads presence at all: every live target's follow-up joins the queue and the drain is the single decision point. Nothing waits longer for it — handle ends in a drain, so a follow-up to an idle target is queued and handed over inside the same call, behind whatever was already queued for that target.

Measured on the live 0.1.64-beta5 daemon by MailDeliveryCheck: ten messages sat staged and drained 77–147s late while six sent afterwards arrived in 0.5s. Order was perfect within each path and meaningless across them. And by MailOrderingCheck on the live room: 28 of 165 consecutive --follow-up pairs to a single target landed in the same minute — roughly one in six times two loops talk to the same peer, a correction can arrive before the thing it corrects.

Test: tenStagedAndSixLaterMessagesArriveInSendOrder (the field shape, 10 + 6), plus probes B and D.

3. A single drain reordered, and drained at walking pace (#304 residual)

The drain re-read presence between items, so a turn ending mid-batch sent [2, 3, 1] — one drain, no overlap, which is why #309's in-flight guard cannot see it. The reading is now taken once per target per pass, before the pass has typed anything into that session, so a batch either goes out in order or waits together.

That also ends a rate nobody had filed. Because delivering makes the target busy, a re-reading drain stopped after the first delivery of every pass and waited for the next tick: MailDeliveryCheck measured about two deliveries per 17s tick, which is why ten staged messages took 147 seconds. A backlog now goes out in one pass.

Tests: aTurnEndingMidDrainDoesNotReorderTheQueue (main: ["staged 2", "staged 3", "staged 1"]) and aBacklogDrainsInOnePassRatherThanOnePerTick (main: 1 of 10 delivered per pass).

4. Re-scoping a watch kept the abandoned topic's wakes (#304 residual)

mail watch --on --topic other is --off for the topic being left. Its staged wakes are dropped, and the drain owes a wake only under the watch standing now — the guard asked whether some watch stood, never whether it still matched the post.

Test: reScopingAWatchDropsTheAbandonedTopicsStagedWakes (main delivers both wakes), plus probe C; probe E keeps the --off-then---on workaround honest.

Evidence

Five tests, each failing on origin/main (8dbf548) for its own reason — main's GraphStore.swift checked out into this worktree with only an inert presenceReadDeadline parameter added so the suite compiles:

Test On main Here
aHungPresenceReadDoesNotStopDeliveryToOtherLoops elapsed 10.05s, neighbour behind the wedge 0.41s ✅
tenStagedAndSixLaterMessagesArriveInSendOrder [staged 1, later 1…later 6, staged 2…staged 10] in send order ✅
aTurnEndingMidDrainDoesNotReorderTheQueue [staged 2, staged 3, staged 1] [1, 2, 3]
reScopingAWatchDropsTheAbandonedTopicsStagedWakes 2 wakes delivered 1 ✅
aBacklogDrainsInOnePassRatherThanOnePerTick [backlog 1] all 10 ✅

Plus MailOrderingCheck's five scripted probes (probe/304-ordering @ 053f83f) carried over verbatim — written against main by a loop that reproduced these independently, and passing here unchanged. FollowUpDrainTests and FollowUpMessageTests are untouched and green, so #309's guarantees still hold.

Kept as one PR

Both halves are gated together and a reader can take them together; splitting now would cost a second review cycle for no gain, and the blocker (the wedge) is in the same file as the rest. The seam is still visible if anyone wants to carve it: the wedge is Deadline.swift + presenceReading(of:) + the lease; the ordering half is deliversLater, the drain's per-pass reading, and the watch re-scope.

Answering the stable-release check

STABLE-CHECK-0.1.64.md (worktrees/stable-check-311) reproduced the wedge on a real graphcoded: control run delivered a bystander's queued mail in ~15s; wedge run — one loop's zmx get … presence hanging — never delivered in 364s with a client attached, zero errors logged. Its four must-fix items, against this branch:

  1. Deadline, timeout ⇒ .unknown. Done, and applied to refreshPresence too, which is its point 3: the poll walked nodes serially through the same unbounded await, so every loop behind the hung one stopped being read at all.
  2. "Make the guard a lease with an expiry, not a bare flag." Done — I was wrong to argue it was belt-on-belt. The question that settled it: is every suspension point inside the guarded region bounded? It is not. deliverToSession is the same PTYProcessSession chain with no deadline of its own — zmx ls to check the session exists (ZmxSessionLauncher.send), a write per chunk via waitUntilFinished(), and sendRemote over ssh for a remote loop. A hang there holds a bare flag for the life of the daemon exactly as the presence read did. So the guard is now a lease: 300s, RemoteEnsureGate.leaseDuration, released only by the drain that still holds it (end(_:token:)'s lesson). Taking over cannot duplicate, because the batch is taken and cleared in one actor step, so a successor finds only what was queued after it.
  3. Observability. A drain that outlives its lease records event=drain-stall held_ms=… queued=… through Add structured diagnostics for daemon IPC requests and broadcasts #289's diagnostics. Frozen and working stop looking identical — the soak's 364 silent seconds are what this line is for.
  4. "Fold the batch back on the way out of every path." Done — the write-back is a defer over remaining + the untouched tail.
  5. "Have deliversLater and the drain read presence the same way." Done by deletion: deliversLater reads no presence at all.

Its DrainWedgeTests are carried over, with the assertions turned round to what this branch does, plus one the report asked for that no deadline can give:

Test On main Here
aBystandersFollowUpIsDeliveredWhenEveryPresenceReadAnswers (their control) passes passes ✅
aHungPresenceReadDoesNotFreezeEveryOtherLoopsFollowUps bystander's mail never arrives delivered ✅
aHungPresenceReadDoesNotStopThePollTickReachingLaterLoops poll asked only the hung node asks both ✅
aHungDeliveryReleasesTheQueueWhenItsLeaseExpires queue held for ever, nothing logged delivered after the lease, event=drain-stall logged ✅

The last one hangs the delivery, not the read — the path the deadline cannot reach — so it is the test that shows the lease earning its place rather than duplicating the bound.

One behaviour change the gate caught

MailroomTests.liveIdleWatcherHearsThePostThroughTheDeliveryChannel asserts that a live idle watcher gets its wake typed in and no "follow-up staged" line — the staging record is the waiting path's, not the live one's. Since every live target's follow-up now joins the queue, recording at queue time described a wait that never happened and gave each watcher a log line per post. The record therefore moves to the first time an item is actually put back, still inside the pass that deferred it, and an item the drain drops (target resolved, or no longer reachable) is written to the log there instead — which is what the queue-time record used to guarantee. That test passes unchanged.

Gate

Gate on eb15c31 (= pushed head), private -derivedDataPath:

Step Exit Result
xcodebuild -scheme graphcode test 0 ** TEST SUCCEEDED ** — 1673 tests / 177 suites / 0 failures (10 new here)
xcodebuild -scheme graphcode-cli build 0
xcodebuild -scheme graphcoded build 0
swiftlint lint 0 0 errors
swift format lint --strict 0 clean
swift build + scripts/cli-smoke.sh 0 five verbs against a throwaway daemon
Linux (gh run 34077784359, head eb15c31) success

Not merging on my own gate.

Trade-off worth naming

A follow-up to an idle target now costs one presence probe (the drain's) where it previously cost none, so a Mailroom post to N idle watchers spends N probes it did not before. In exchange the drain spends one probe per target per pass instead of one per message, which a queue of any depth more than repays — and it is the same probe the 15s poll already makes.

Closes #311. Closes #304.

🤖 Generated with Claude Code

https://claude.ai/code/session_014D7evLSBWCnNeumHAWHH5S

scgopi and others added 5 commits September 6, 2026 18:48
#304)

Four defects on one seam — how a staged follow-up decides when to be
delivered — with a test each, because a combined test that passes says
nothing about which half works.

**The presence read had no deadline.** `onReadPresence` reaches
`PTYProcessSession.waitCollectingOutput`, which ends only when the probe's
`terminationHandler` closes the stream, and `ssh`'s `ConnectTimeout=10`
bounds the connect rather than a command hanging on a host that has gone
away. One such read held `isDrainingFollowUps` for the life of the daemon
and froze staged delivery for every loop in the project — and a frozen
queue reports exactly what an empty one reports. Every reading in the
store now goes through one bounded `presenceReading(of:)`; a read that
runs out of time is `.unknown`, never a state, which is the distinction
#286 established for a `zmx` probe that could not run. An unknown target
keeps its message queued and is asked again next pass: not delivered
blindly, not busy for ever.

**Two readings decided one question.** `deliversLater` consulted the
cached `node.presence` the poll last wrote while the drain took a live
one, so a follow-up staged afterwards was typed in ahead of a queue still
being worked through. Measured on the live 0.1.64-beta5 daemon: ten
messages drained 77–147s late while six sent afterwards arrived in 0.5s.
`deliversLater` no longer reads presence at all — every live target's
follow-up joins the queue and the drain is the single decision point.
`handle` ends in a drain, so nothing waits longer for it.

**A single drain reordered.** The drain re-read presence between items, so
a turn ending mid-batch sent [2, 3, 1] with no overlapping drain anywhere
— which is why #309's non-reentrancy guard cannot see it. The reading is
now taken once per target per pass. That also ends a rate nobody had
filed: delivering into a session is what makes it busy, so a re-reading
drain stopped after the first delivery of every pass and waited for the
next tick — ten staged messages took 147 seconds. A backlog now goes out
in one pass.

**Re-scoping a watch kept the old topic's wakes.** `mail watch --on
--topic other` is `--off` for the topic being left; its staged wakes are
dropped, and the drain owes a wake only under the watch standing now.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014D7evLSBWCnNeumHAWHH5S
Written against main by the loop that reproduced these defects
independently (branch probe/304-ordering, 053f83f), scripted rather than
timed: each one drives the store's presence readings from a fixed script,
so a failure is a defect and never a race that happened to land. All five
fail on main — reorder within one drain, the queue jump from a cached
reading, the same jump reached by an ordinary partly-drained queue, the
abandoned topic's wake, and the --off/--on workaround — and all five pass
here unchanged, which is the point of taking them verbatim.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014D7evLSBWCnNeumHAWHH5S
Every live target's follow-up now joins the queue and `handle` ends in a
drain, so a message to an idle session is queued and handed over inside
the same call. Recording "follow-up staged" at queue time then described
a wait that never happened — and gave every Mailroom watcher a log line
per post it was woken for, on top of the wake it received instantly.
`MailroomTests.liveIdleWatcherHearsThePostThroughTheDeliveryChannel`
holds the property: a live idle watcher gets the delivery and no staging
line.

The record moves to the first time an item is actually put back, which is
still inside the pass that deferred it — nothing the queue owes can be
lost to a daemon restart. An item the drain drops because its target
resolved or is no longer reachable lands in the log too, which the old
queue-time record was what guaranteed.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014D7evLSBWCnNeumHAWHH5S
The stable-release check's reading of the wedge (STABLE-CHECK-0.1.64.md,
worktrees/stable-check-311) was that the drain empties `pendingFollowUps`
into a local batch before its first `await`, so a walk that never returns
strands the whole queue in a variable. The deadline is what stops that
walk from never returning; this is the other half of its request —
whatever exit the pass takes, what it did not resolve goes back on the
queue rather than out of scope with the locals.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014D7evLSBWCnNeumHAWHH5S
The deadline bounds the presence read. It does not bound the *class*:
`deliverToSession` is the same `PTYProcessSession` chain with no deadline
of its own — `zmx ls` to check the session exists, a write per chunk, and
`ssh` for a remote loop — so a hang there would hold a bare flag for the
life of the daemon exactly as the presence read did, and every loop in
the project would stop receiving mail with nothing logged. That failure
was measured on a real `graphcoded`: 364 seconds, zero errors
(STABLE-CHECK-0.1.64.md). `RemoteEnsureGate` rejects the plain flag for
this same chain and for this same reason.

So the guard expires. A drain that outlives its lease is a wedge by
definition: the next one records `event=drain-stall` through #289's
diagnostics — frozen and working must stop looking identical — and takes
the queue on. Taking over cannot duplicate anything, because the batch
was taken and cleared in one actor step, so the successor finds only what
was queued after it; and the lease is released only by the drain that
still holds it, the mistake `RemoteEnsureGate.end(_:token:)` documents.

Tests are `StableSoakCheck`'s wedge rig, assertions turned round to what
this branch does, plus the one no deadline can give:
`aHungDeliveryReleasesTheQueueWhenItsLeaseExpires` hangs the *delivery*
and shows the bystander's mail arriving after the lease expires, with the
stall in the log.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014D7evLSBWCnNeumHAWHH5S
@scgopi
scgopi merged commit a5ae15a into main Sep 7, 2026
1 check passed
scgopi added a commit that referenced this pull request Sep 7, 2026
#316 bounded the presence read, but drainPendingFollowUps still awaited
deliverToSession unbounded in the same walk — the stable-release check's
DeliveryWedgeTests reproduce the freeze reached through the send instead:
one loop's hung zmx send held the queue for the lease's whole 300s,
every other loop's staged mail unmoving and silent.

The send now has the same withDeadline the presence read has (45s, the
loser abandoned rather than cancelled-and-waited). What the deadline
drops is staged to the target's memory log and taken off the queue, so
the target still reads it at its next wake — and a delivery that fails
without hanging is recorded the same way, which the old code silently
dropped. A delivery-stall line in the daemon log keeps frozen and
working looking different.

The lease stays: it is the backstop for the awaits that are not the
drain's walk (stop requests, nudges), not a licence to park the queue
for minutes first.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

1 participant