From 0af50530030a5f7dfcbc2f7e11172c42886eedec Mon Sep 17 00:00:00 2001 From: schickling-assistant <261620128+schickling-assistant@users.noreply.github.com> Date: Tue, 21 Jul 2026 14:13:29 +0200 Subject: [PATCH] Reland: make an always-on agent reachable, and stop reporting liveness it hasn't earned Restores the content of PR #106, which was merged without review and reverted in PR #107. Opened as a draft for proper review. No content changes from the original: the resulting tree is byte-identical to e646250. Refs #101, #102 --- src/commands/agents.ts | 103 +++++++- src/commands/ding.ts | 112 +++++++++ src/commands/status.ts | 121 +++++++++ src/common.ts | 25 ++ src/index.ts | 21 ++ tests/unit/agents.test.ts | 111 +++++++++ tests/unit/ding.test.ts | 365 ++++++++++++++++++++++++++++ tests/unit/status-staleness.test.ts | 119 ++++++++- 8 files changed, 968 insertions(+), 9 deletions(-) diff --git a/src/commands/agents.ts b/src/commands/agents.ts index d21f42b..c4e3ea6 100644 --- a/src/commands/agents.ts +++ b/src/commands/agents.ts @@ -31,14 +31,29 @@ import { } from '../common.ts'; import { type State } from '../types.ts'; -import { readIdentityStatus } from './status.ts'; +import { readIdentityLiveness } from './status.ts'; export interface AgentSummary { /** The agent's name. Field kept as `identity` for back-compat with * embedder destructures; will rename to `agent` in a follow-up. */ identity: string; + /** Derived, trust-windowed state — UNCHANGED semantics. Still what + * `--status` filters on. See `live`/`statusMtimeMs` for freshness. */ status: State; name: string | null; + /** #102: freshness, so a roster reader can't mistake a stale value + * for a current one. `live` uses the shared STATUS_LIVENESS_MS + * window; `recorded` preserves the on-disk value across it so a + * stale-but-was-`busy` agent stays distinguishable from one that + * cleanly went `offline`. + * + * Note `statusMtimeMs` is the ABSOLUTE mtime, not an age. An age + * would make two back-to-back reads of an unchanged bus return + * different data; callers render the relative form themselves (see + * `formatAge`). Mirrors how `lastActivity` already reports mtimes. */ + live: boolean; + statusMtimeMs: number | null; + recorded: State | null; } export interface AgentSummaryEnriched extends AgentSummary { @@ -82,11 +97,17 @@ export function getAgents( opts: GetAgentsOpts = {} ): AgentSummary[] | AgentSummaryEnriched[] { const ids = listAgents(root); - const base: AgentSummary[] = ids.map((id) => ({ - identity: id, - status: readIdentityStatus(id, root), - name: readNameFile(id, root), - })); + const base: AgentSummary[] = ids.map((id) => { + const l = readIdentityLiveness(id, root); + return { + identity: id, + status: l.status, + name: readNameFile(id, root), + live: l.live, + statusMtimeMs: l.mtimeMs, + recorded: l.recorded, + }; + }); const filtered = opts.status !== undefined && opts.status !== '' ? base.filter((m) => m.status === opts.status) @@ -252,6 +273,18 @@ function agentsHelp(name: string): string { ' --status STATE only agents in STATE (available|busy|away|dnd|offline).\n' + ' --json machine-readable array.\n' + ' --enrich (with --json) add inbox counts + last-activity.\n\n' + + ' Freshness: a status value is only as good as its mtime, so one\n' + + ' that has not been touched recently is shown with its age:\n' + + ' available touched recently\n' + + ' available (3m ago) last touched 3m ago\n' + + ' unknown (was busy, 22m ago) too old to trust; last claimed `busy`\n' + + ' The age is a fact, not a verdict: agents have different status\n' + + ' writers (a ding heartbeat touches every 30s, an MCP server every\n' + + ' 5min), so how old is too old depends on the agent. --json carries\n' + + ' `live` (per the shared STATUS_LIVENESS_MS window) plus\n' + + ' `statusMtimeMs` / `recorded` for consumers that know their own\n' + + ' cadence. The `status` field itself is unchanged, as is what\n' + + ' --status filters on.\n\n' + ' Examples:\n' + ` ${name} agents # id / status / name, tab-separated\n` + ` ${name} agents --status available # only agents marked available\n` + @@ -300,11 +333,67 @@ export function cmdAgentsCli( return 0; } for (const m of r.items) { - ctx.stdout(`${m.identity}\t${m.status}\t${m.name ?? ''}\n`); + ctx.stdout( + `${m.identity}\t${renderStatusCell(m)}\t${m.name ?? ''}\n` + ); } return 0; } +/** + * #102: the status cell, annotated with the AGE of the value. + * + * `st agents` used to print the derived state bare, so a status file + * last touched minutes ago rendered identically to one touched a second + * ago. The value was never wrong exactly — it was unqualified, and a + * roster command is precisely where "as of when?" matters. + * + * Deliberately a FACT ("3m ago"), not a VERDICT ("stale"). `st agents` + * enumerates every agent under the root, and different agents have + * different status writers with different cadences: the ding heartbeat + * touches every 30s, but an MCP-server-backed agent only refreshes + * every STATUS_REFRESH_MS (5 min). A single global "this one is stale" + * verdict cannot be right for both — calling a healthy MCP agent stale + * for 3 of every 5 minutes would just be a new way of being wrong. + * + * So the roster reports the age and lets the reader judge. A consumer + * that KNOWS its agents run a ding (convoy) applies STATUS_LIVENESS_MS + * via the exported `live` field / `readIdentityLiveness`, which is + * where a verdict can actually be justified. + * + * Shapes: + * available touched inside the liveness window + * available (3m ago) older than that — stated, not judged + * unknown (was busy, 22m ago) past the trust window; derived state is + * `unknown`, but we still say what it last + * claimed, because "was busy and went + * quiet" and "cleanly offline" are + * different facts + * offline no status file at all; nothing to age + */ +function renderStatusCell(m: AgentSummary, now = Date.now()): string { + if (m.statusMtimeMs === null) return m.status; // no file → nothing to qualify + if (m.live) return m.status; + const age = `${formatAge(now - m.statusMtimeMs)} ago`; + // Trust window blew past: `status` is `unknown`, so surface what the + // file still records rather than dropping the signal entirely. + if (m.status === 'unknown' && m.recorded !== null) { + return `unknown (was ${m.recorded}, ${age})`; + } + return `${m.status} (${age})`; +} + +/** Compact age: `45s`, `3m`, `2h`, `4d`. */ +export function formatAge(ms: number): string { + const s = Math.max(0, Math.round(ms / 1000)); + if (s < 60) return `${s}s`; + const m = Math.round(s / 60); + if (m < 60) return `${m}m`; + const h = Math.round(m / 60); + if (h < 24) return `${h}h`; + return `${Math.round(h / 24)}d`; +} + // ─── Deprecated aliases (brief-009 item 3) ───────────────────────────── // // `members` was renamed to `agents`. The old names remain as diff --git a/src/commands/ding.ts b/src/commands/ding.ts index 173ee40..29ac3bb 100644 --- a/src/commands/ding.ts +++ b/src/commands/ding.ts @@ -478,8 +478,64 @@ export async function runDing(deps: DingDeps): Promise { | { kind: 'failed' } | { kind: 'held'; inputText: string; staleCount: number }; + // ─── Delivery-stall tracking (#101) ─────────────────────────────── + // + // The pane guard deliberately NEVER force-submits into a frame that + // is still changing: a submit landing mid-turn seeds Claude Code's + // queued-input replay bug (see the comment in `guardedDeliver` and + // the "keeps HOLDING, never force-submits" regression test). That + // decision stands — but it means a target pane that keeps changing + // holds every poke for as long as it keeps changing, with no upper + // bound. + // + // Before this fix that state was INVISIBLE and, worse, DISHONEST: + // the hold logged only under ST_DING_DEBUG, while the status-refresh + // tick (which is entirely decoupled from delivery) kept bumping the + // identity's status mtime. Senders therefore read `available` from an + // agent whose mail the sidecar was demonstrably not delivering. + // + // `deliveryStalled` closes that gap. Once a message has been held + // PAST the hold cap, the sidecar has proven it cannot currently + // deliver, so it (a) says so loudly, once, on stderr and (b) stops + // refreshing the status file. The mtime then freezes and readers + // derive staleness through the normal path — the same death-coupling + // the session-gone watch already relies on. A successful delivery + // clears the stall and the heartbeat resumes. + // + // Invariant: a sidecar must not write liveness it has not earned. + let deliveryStalled = false; + /** Loud-log the stall exactly once per stall episode, not per retry. */ + let loggedStall = false; + + function markDeliveryStalled(ev: BufferedEvent, holds: number): void { + deliveryStalled = true; + if (loggedStall) return; + loggedStall = true; + log( + `st ding: DELIVERY STALLED — "${ev.filename}" has been held ` + + `${holds} times (cap ${maxHolds}) because pty session ` + + `"${deps.ptySession}" is never static long enough to submit ` + + `into safely. The message is NOT lost — it stays in the inbox ` + + `and is retried every ${holdRetryMs}ms — but it will not be ` + + `delivered until the pane goes idle. Suspending the status ` + + `heartbeat for "${deps.identity}" so peers stop reading this ` + + `agent as available while its mail is undeliverable.\n` + ); + } + + function clearDeliveryStall(): void { + if (!deliveryStalled) return; + deliveryStalled = false; + loggedStall = false; + log( + `st ding: delivery recovered for "${deps.identity}" — resuming ` + + `the status heartbeat.\n` + ); + } + async function normalDeliver(ev: BufferedEvent): Promise { const ok = await deliver(send, deps.ptySession, ev, log); + if (ok) clearDeliveryStall(); return ok ? { kind: 'delivered' } : { kind: 'failed' }; } @@ -525,6 +581,7 @@ export async function runDing(deps: DingDeps): Promise { return { kind: 'failed' }; } dbg(`preserve-delivered ${ev.filename} (kept un-submitted input)`); + clearDeliveryStall(); return { kind: 'delivered' }; } @@ -577,6 +634,10 @@ export async function runDing(deps: DingDeps): Promise { if (!hasInput) { if (a.frameChanged) { dbg(`frame changing (mid-turn) → holding ${ev.filename} (hold ${holds + 1}; cap won't force into an active turn)`); + // #101: the hold itself is correct (never submit mid-turn), but + // past the cap the sidecar has proven it is not delivering — + // say so, and stop asserting liveness we have not earned. + if (forceCap) markDeliveryStalled(ev, holds + 1); return { kind: 'held', inputText: '', staleCount: 0 }; } return normalDeliver(ev); // frame static (idle / walked away) → safe to submit @@ -594,6 +655,9 @@ export async function runDing(deps: DingDeps): Promise { ev.lastInputText !== inputText; if (changed) { dbg(`pane active (frame/input changing) → holding ${ev.filename} (hold ${holds + 1})`); + // #101: same invariant as the no-input branch above — a pane that + // stays active past the cap means we are not delivering. + if (forceCap) markDeliveryStalled(ev, holds + 1); return { kind: 'held', inputText, staleCount: 1 }; } const staleCount = (ev.inputStaleCount ?? 1) + 1; @@ -846,6 +910,19 @@ export async function runDing(deps: DingDeps): Promise { deps.statusRefreshIntervalMs ?? LIVENESS_HEARTBEAT_MS; let statusRefreshTimer: ReturnType | undefined; function runStatusRefreshTick(): void { + // #101 invariant: a sidecar must not write liveness it has not + // earned. While delivery is stalled (a message held past the cap on + // a pane that never goes static) this sidecar is NOT surfacing the + // agent's mail — refreshing the mtime here would advertise an + // availability it cannot honor. Skip the touch instead: the mtime + // freezes, and every reader derives staleness through the existing + // path. `markDeliveryStalled` already logged the reason once. + if (deliveryStalled) { + dbg( + `status refresh suppressed for "${deps.identity}" — delivery stalled` + ); + return; + } const outcome = refreshIdentityStatus(deps.identity, deps.st.root); if (outcome === 'error') { log( @@ -895,8 +972,37 @@ export async function runDing(deps: DingDeps): Promise { } } } + // #106 follow-up: prune messages the agent archived while they + // were buffered, BEFORE the status gate below. Two reasons this + // cannot wait for the drain loop's own `stillInInbox` check: + // + // 1. The drain never runs while the identity is busy/dnd (the + // SUPPRESS_STATES return below). A busy agent that reads and + // archives its own mail — literally the documented boot + // ritual, "drain your inbox" — would otherwise leave the + // archived event parked in the buffer indefinitely. + // 2. `deliveryStalled` is cleared on the drained checkpoints + // below. If archived events are never pruned, the buffer + // never drains, and a stall outlives the message that caused + // it — permanently suspending the heartbeat of a healthy + // agent whose inbox is empty. + // + // Archived means "no longer needs delivery" regardless of status, + // so this prune is status-independent by construction. + for (let i = buffer.length - 1; i >= 0; i -= 1) { + if (!stillInInbox(buffer[i]!.filename)) { + dbg( + `buffered message ${buffer[i]!.filename} archived while held → dropping stale poke` + ); + buffer.splice(i, 1); + } + } if (buffer.length === 0 && readPending.length === 0) { disarmTimer(); + // Nothing is awaiting delivery, so nothing is undeliverable: + // the stall's cause is gone and the stall must not outlive it. + // (No-op unless a stall is actually up.) + clearDeliveryStall(); return; } let state: State; @@ -969,6 +1075,12 @@ export async function runDing(deps: DingDeps): Promise { if (deferred.length > 0) buffer.push(...deferred); if (buffer.length === 0 && readPending.length === 0) { disarmTimer(); + // Same invariant as the pre-gate checkpoint above: the buffer + // drained, so no held message remains undeliverable. Note this + // deliberately does NOT fire while a second message is still + // deferred — a stall must survive as long as ANY message is + // still undeliverable, which is the whole point of #106. + clearDeliveryStall(); } } finally { flushing = false; diff --git a/src/commands/status.ts b/src/commands/status.ts index 9cbb26b..baf903b 100644 --- a/src/commands/status.ts +++ b/src/commands/status.ts @@ -22,6 +22,7 @@ import { resolveIdentity, SETTABLE_STATES, STATES, + STATUS_LIVENESS_MS, STATUS_STALE_MS, type State, statusPath, @@ -111,6 +112,126 @@ export function readIdentityStatus(identity: string, root: string): State { return readState(statusPath(identity, root)); } +/** + * The shared freshness verdict for one identity's status file. + * + * `st agents` said `available` at the same instant `convoy ls --tree` + * said `DEAD (status stale 3m ago)`. Both were reading the same file; + * they disagreed because each had picked its own window. This is the + * one definition every consumer should read through so that stops + * happening. + * + * Note the two fields are answers to two different questions, and a + * caller generally wants both: + * + * `status` — what `st status` / `readIdentityStatus` return. Applies + * the TRUST window (STATUS_STALE_MS, 15 min) and so + * collapses to `unknown` only when the value itself is + * no longer believable. + * `live` — whether the agent is demonstrably alive right now, + * per the LIVENESS window (STATUS_LIVENESS_MS, 2 min). + * + * `recorded` deliberately survives both windows. An identity that was + * `busy` and went stale is NOT the same as one that cleanly went + * `offline`, and collapsing them loses the signal that tells you + * "something died mid-work" from "something shut down". + */ +export interface StatusLiveness { + /** Derived state, trust-windowed. Same value `st status` prints. */ + status: State; + /** The literal on-disk value, whatever its age. `null` when the file + * is missing or unreadable — distinct from a recorded `offline`. */ + recorded: State | null; + /** Age of the status file's mtime in ms, relative to the `now` this + * verdict was taken at; `null` when there is no file. Point-in-time + * by nature — persist {@link mtimeMs} instead if you need something + * that compares equal across two reads of an unchanged bus. */ + ageMs: number | null; + /** Absolute mtime of the status file; `null` when there is no file. */ + mtimeMs: number | null; + /** True iff the file exists and is fresher than STATUS_LIVENESS_MS. */ + live: boolean; +} + +/** + * Read an identity's status once and return the full freshness verdict. + * + * Exactly one `stat` and (when the file exists) one `read` — every field + * below is derived from that single snapshot, deliberately WITHOUT + * delegating to `readState`. Delegating would re-`stat` and re-`read` + * the same path, and — the reason that matters — `status` and `recorded` + * would then be answers about two different points in time: a status + * write landing between the two reads could return, say, `status: busy` + * alongside `recorded: 'available'`, a pair that never existed on disk. + * One snapshot makes every field of the returned verdict mutually + * consistent by construction. + * + * `status` applies exactly the `readState` rules (missing → `offline`, + * mtime older than STATUS_STALE_MS → `unknown`, unreadable or malformed + * → `offline`), against the caller's `now` rather than a second + * `Date.now()`, so an injected `now` governs the whole verdict instead + * of only `ageMs` / `live`. + */ +export function readIdentityLiveness( + identity: string, + root: string, + opts: { livenessMs?: number; now?: number } = {} +): StatusLiveness { + const path = statusPath(identity, root); + const livenessMs = opts.livenessMs ?? STATUS_LIVENESS_MS; + const now = opts.now ?? Date.now(); + + // The single stat. A throw means missing/unreadable — `offline`, and + // no age is knowable. (Also collapses the old existsSync + statSync + // pair, which was itself a stat-then-stat TOCTOU.) + let mtimeMs: number | null = null; + try { + mtimeMs = statSync(path).mtimeMs; + } catch { + mtimeMs = null; + } + if (mtimeMs === null) { + return { + status: 'offline', + recorded: null, + ageMs: null, + mtimeMs: null, + live: false, + }; + } + const ageMs = now - mtimeMs; + + // The single read. Its first line is the recorded value; `status` is + // that same value put through the trust window. + let recorded: State | null = null; + let readOk = false; + try { + const first = (readFileSync(path, 'utf8').split('\n')[0] ?? '').replace( + /[\s]/g, + '' + ); + readOk = true; + if (isValidState(first)) recorded = first as State; + } catch { + recorded = null; + } + + const status: State = + ageMs > STATUS_STALE_MS + ? 'unknown' // too old to believe, whatever it says + : !readOk || recorded === null + ? 'offline' // unreadable or malformed never propagates + : recorded; + + return { + status, + recorded, + ageMs, + mtimeMs, + live: ageMs <= livenessMs, + }; +} + export function isValidState(s: string): s is State { return (STATES as readonly string[]).includes(s); } diff --git a/src/common.ts b/src/common.ts index dd0a337..72de0d3 100644 --- a/src/common.ts +++ b/src/common.ts @@ -100,6 +100,31 @@ export const STATUS_REFRESH_MS = 5 * 60 * 1000; * just anti-`unknown`-drift. See commands/ding.ts + docs/KNOWN-LIMITS.md. */ export const LIVENESS_HEARTBEAT_MS = 30 * 1000; +/** The T in the cross-machine liveness contract: how old a status file's + * mtime may get before we stop calling the agent *live*. This is the + * READER half of the R=30s/T~=120s pair that LIVENESS_HEARTBEAT_MS is + * the writer half of — 4 missed ding heartbeats. + * + * Deliberately distinct from {@link STATUS_STALE_MS}, and much tighter. + * The two answer different questions and MUST NOT be collapsed: + * + * STATUS_STALE_MS (15 min) — "do we still trust the recorded value?" + * Sized for the SLOWEST writer, the MCP server's 5-min refresh. + * Past it the value is untrustworthy and reads as `unknown`. + * + * STATUS_LIVENESS_MS (2 min) — "is this agent live right now?" + * Sized for the ding's 30s heartbeat. Past it the agent is not + * demonstrably alive, but the recorded value is still the best + * information we have about what it was doing. + * + * Tightening STATUS_STALE_MS to this value would be wrong: an agent + * kept fresh only by the 5-min MCP refresh would flap into `unknown` + * between every refresh. Exported so every consumer (`st agents`, + * convoy, any future roster) inherits ONE definition of "live" instead + * of each picking its own window — the divergence that made `st agents` + * and `convoy ls --tree` disagree about the same identity. */ +export const STATUS_LIVENESS_MS = 2 * 60 * 1000; + /** brief-030: how often the MCP server runs its tidy-check tick (the * drift detector that nudges an agent when their inbox is out of date * relative to the boot ritual). Default 20 minutes — long enough that diff --git a/src/index.ts b/src/index.ts index 5d93de2..1c0d814 100644 --- a/src/index.ts +++ b/src/index.ts @@ -102,6 +102,27 @@ export { yamlQuote, } from './common.ts'; +// ─── Status freshness contract (#102) ────────────────────────────────── +// +// Exported so every consumer inherits ONE definition of "live" rather +// than each picking its own window — which is how `st agents` and +// `convoy ls --tree` ended up disagreeing about the same identity at +// the same instant. See the doc comments on the two constants: they +// answer different questions and must not be collapsed into one. + +export { + LIVENESS_HEARTBEAT_MS, + STATUS_LIVENESS_MS, + STATUS_REFRESH_MS, + STATUS_STALE_MS, +} from './common.ts'; + +export { + readIdentityLiveness, + readIdentityStatus, + type StatusLiveness, +} from './commands/status.ts'; + // ─── Agents + overview shapes (brief-028, renamed in brief-009 item 3) ─ export { diff --git a/tests/unit/agents.test.ts b/tests/unit/agents.test.ts index 3fdb9f2..a8b45ce 100644 --- a/tests/unit/agents.test.ts +++ b/tests/unit/agents.test.ts @@ -12,7 +12,9 @@ import { join } from 'node:path'; import { afterEach, beforeEach, describe, expect, it } from 'vitest'; import { + cmdAgentsCli, cmdMembers, + formatAge, listIdentities, type MemberSummary, type MemberSummaryEnriched, @@ -249,3 +251,112 @@ describe('cmdMembers --enrich', () => { function mapBy(items: MemberSummary[]): Record { return Object.fromEntries(items.map((m) => [m.identity, m])); } + +// ─── #102: roster freshness ──────────────────────────────────────────── +// +// `st agents` printed the derived state bare, so a status file last +// touched minutes ago rendered identically to one touched a second ago. +// A roster command is exactly where "as of when?" matters — this is +// what let `st agents` and `convoy ls --tree` disagree out loud about +// the same identity at the same instant. +// +// NOTE the deliberate non-change: `status` (and therefore what +// `--status` filters on) keeps its old meaning. Only the rendered cell +// gains a qualifier, and --json gains additive fields. +describe('agents: status freshness (#102)', () => { + function backdateStatus(id: string, ageMs: number): void { + const p = join(stRoot, id, 'status'); + const t = new Date(Date.now() - ageMs); + utimesSync(p, t, t); + } + + function render(): string { + let out = ''; + cmdAgentsCli([], { + stRoot, + env: {}, + stdout: (s: string) => { + out += s; + }, + stderr: () => {}, + } as unknown as Parameters[1]); + return out; + } + + it('fresh status renders bare (no annotation noise on a live roster)', () => { + setupIdentity('alice'); + setStatus('alice', 'available'); + expect(render()).toBe('alice\tavailable\t\n'); + }); + + it('the reported case: 3m-old `available` is annotated with its age', () => { + setupIdentity('alice'); + setStatus('alice', 'available'); + backdateStatus('alice', 3 * 60_000); + expect(render()).toContain('available (3m ago)'); + }); + + it('past the trust window: shows `unknown` but keeps what it last claimed', () => { + setupIdentity('alice'); + setStatus('alice', 'busy'); + backdateStatus('alice', 25 * 60_000); + const out = render(); + expect(out).toContain('unknown (was busy, 25m ago)'); + }); + + it('stale-was-busy is distinguishable from stale-was-offline', () => { + setupIdentity('alice'); + setStatus('alice', 'busy'); + backdateStatus('alice', 25 * 60_000); + setupIdentity('carol'); + setStatus('carol', 'offline'); + backdateStatus('carol', 25 * 60_000); + const out = render(); + expect(out).toContain('was busy'); + expect(out).toContain('was offline'); + }); + + it('no status file at all → plain `offline`, nothing to qualify', () => { + setupIdentity('alice'); + expect(render()).toBe('alice\toffline\t\n'); + }); + + it('--status filtering keeps its old meaning (no semantic drift)', () => { + // The derived `status` field is untouched by the annotation work, so + // a stale-but-trusted `available` still matches `--status available`. + setupIdentity('alice'); + setStatus('alice', 'available'); + backdateStatus('alice', 3 * 60_000); + const items = cmdMembers({ stRoot, status: 'available' }).items; + expect(items.map((m) => m.identity)).toEqual(['alice']); + }); + + it('--json exposes live / statusMtimeMs / recorded additively', () => { + setupIdentity('alice'); + setStatus('alice', 'busy'); + backdateStatus('alice', 5 * 60_000); + const m = cmdMembers({ stRoot }).items[0] as MemberSummary; + expect(m.status).toBe('busy'); // unchanged + expect(m.live).toBe(false); + expect(m.recorded).toBe('busy'); + expect(m.statusMtimeMs).not.toBeNull(); + expect(Date.now() - (m.statusMtimeMs as number)).toBeGreaterThan( + 4 * 60_000 + ); + }); + + it('two back-to-back reads of an unchanged bus compare equal', () => { + // Regression guard: an `ageMs` field here would make every read + // differ from the last. Absolute mtimes keep the shape repeatable. + setupIdentity('alice'); + setStatus('alice', 'available'); + expect(cmdMembers({ stRoot }).items).toEqual(cmdMembers({ stRoot }).items); + }); + + it('formatAge renders compact units', () => { + expect(formatAge(45_000)).toBe('45s'); + expect(formatAge(3 * 60_000)).toBe('3m'); + expect(formatAge(2 * 60 * 60_000)).toBe('2h'); + expect(formatAge(4 * 24 * 60 * 60_000)).toBe('4d'); + }); +}); diff --git a/tests/unit/ding.test.ts b/tests/unit/ding.test.ts index f6857d2..f7c776f 100644 --- a/tests/unit/ding.test.ts +++ b/tests/unit/ding.test.ts @@ -3057,3 +3057,368 @@ describe('runDing — brief-036 typing-aware pane guard', () => { await r.done; }); }); + +// ─── #101: delivery-stall must not advertise unearned liveness ───────── +// +// Reproduced defect: the pane guard deliberately never force-submits +// into a still-changing frame (that would seed Claude Code's queued- +// input replay bug — see the "keeps HOLDING, never force-submits" +// test above). Correct in isolation, but the status-refresh tick was +// entirely decoupled from delivery, so a sidecar holding every poke on +// a perpetually-busy pane kept bumping the identity's status mtime. +// Senders read `available` from an agent whose mail was not being +// surfaced — liveness the sidecar had not earned. +// +// The fix does NOT change the hold decision. It couples the heartbeat +// to delivery health: held past the cap → stop touching the status +// file (and say so once, loudly); delivered → resume. +describe('ding: delivery stall suspends the status heartbeat (#101)', () => { + let scratch: string; + let stRoot: string; + let statusFile: string; + let fake: FakeSt; + let sender: FakeSender; + const ID = 'bob'; + + beforeEach(() => { + scratch = mkdtempSync(join(tmpdir(), 'st-ding-stall-')); + stRoot = join(scratch, 'smalltalk'); + mkdirSync(join(stRoot, ID, 'inbox'), { recursive: true }); + mkdirSync(join(stRoot, ID, 'archive'), { recursive: true }); + statusFile = join(stRoot, ID, 'status'); + fake = makeFakeSt(asIdentity(ID), stRoot); + sender = makeFakeSender(); + }); + afterEach(() => { + fake.endWatch(); + rmSync(scratch, { recursive: true, force: true }); + }); + + function makePeeker(frames: () => string): { + peek: PtyPeeker; + count: () => number; + } { + let count = 0; + return { + peek: async () => { + count += 1; + return { status: 0, stdout: frames(), stderr: '' }; + }, + count: () => count, + }; + } + + async function waitFor( + pred: () => boolean, + timeoutMs = 3000 + ): Promise { + const start = Date.now(); + while (!pred()) { + if (Date.now() - start > timeoutMs) return; + await new Promise((r) => setTimeout(r, 5)); + } + } + + it('held past the cap on a busy pane → stops refreshing status, warns once', async () => { + writeFileSync(statusFile, 'available\n'); + const oldT = new Date(Date.now() - 60_000); + utimesSync(statusFile, oldT, oldT); + const mtimeBefore = statSync(statusFile).mtimeMs; + + let n = 0; + const peeker = makePeeker(() => `frame ${n++}`); // never static + let err = ''; + const r = startDing({ + st: fake.st, + ptySend: sender.send, + identity: asIdentity(ID), + paneGuard: true, + ptyPeek: peeker.peek, + peekDiffMs: 1, + holdRetryMs: 15, + maxHolds: 1, // trip the cap quickly + statusRefreshIntervalMs: 20, + intervalMs: 10, + stderr: (s) => { + err += s; + }, + }); + fake.setMessage('1714826789010-aaaaaa.md', { from: 'alice' }); + fake.pushEvent('1714826789010-aaaaaa.md'); + + // Let it hold well past the cap and let several refresh ticks fire. + await waitFor(() => err.includes('DELIVERY STALLED')); + const mtimeAtStall = statSync(statusFile).mtimeMs; + await new Promise((res) => setTimeout(res, 120)); // ~6 refresh ticks + + expect(sender.calls()).toHaveLength(0); // still held (unchanged behavior) + expect(err).toContain('DELIVERY STALLED'); + // Warned exactly once, not once per retry. + expect(err.match(/DELIVERY STALLED/g)).toHaveLength(1); + // The heartbeat stopped: mtime did not advance after the stall. + // (Ticks that fired BEFORE the cap was reached are legitimate — + // suppression starts when the sidecar has proven it can't deliver, + // not before. So compare against the stall instant, not the start.) + expect(statSync(statusFile).mtimeMs).toBe(mtimeAtStall); + void mtimeBefore; + // The recorded value is left alone — we suppress the touch, we do + // not invent a state. + expect(readFileSync(statusFile, 'utf8').trim()).toBe('available'); + + r.ac.abort(); + await r.done; + }); + + it('pane goes idle → delivers, stall clears, heartbeat resumes', async () => { + writeFileSync(statusFile, 'available\n'); + const oldT = new Date(Date.now() - 60_000); + utimesSync(statusFile, oldT, oldT); + const mtimeBefore = statSync(statusFile).mtimeMs; + + let busy = true; + let n = 0; + const peeker = makePeeker(() => + busy ? `frame ${n++}` : 'idle output line' + ); + let err = ''; + const r = startDing({ + st: fake.st, + ptySend: sender.send, + identity: asIdentity(ID), + paneGuard: true, + ptyPeek: peeker.peek, + peekDiffMs: 1, + holdRetryMs: 15, + maxHolds: 1, + statusRefreshIntervalMs: 20, + intervalMs: 10, + stderr: (s) => { + err += s; + }, + }); + fake.setMessage('1714826789010-aaaaaa.md', { from: 'alice' }); + fake.pushEvent('1714826789010-aaaaaa.md'); + + await waitFor(() => err.includes('DELIVERY STALLED')); + const mtimeAtStall = statSync(statusFile).mtimeMs; + await new Promise((res) => setTimeout(res, 100)); // several ticks + expect(statSync(statusFile).mtimeMs).toBe(mtimeAtStall); // suspended + void mtimeBefore; + + busy = false; // agent finishes its turn + await waitFor(() => sender.calls().length > 0); + expect(sender.calls()).toHaveLength(1); // delivered once static + + await waitFor(() => statSync(statusFile).mtimeMs > mtimeAtStall); + expect(statSync(statusFile).mtimeMs).toBeGreaterThan(mtimeAtStall); + expect(err).toContain('delivery recovered'); + + r.ac.abort(); + await r.done; + }); + + // #106 follow-up: the stall must not outlive the condition that + // caused it. The original fix cleared `deliveryStalled` ONLY on a + // successful delivery — but the held message's most likely fate is + // never being delivered at all: the agent reads and archives it + // itself (the documented boot ritual is literally "drain your + // inbox"). The poke is then dropped as a stale poke, no delivery ever + // happens, and the stall — hence the suspended heartbeat — became + // permanent for a perfectly healthy agent. That turns a transient + // "unreachable while busy" into a permanent "reads dead", which is + // worse than the defect #106 set out to fix. + // + // Precondition these tests encode explicitly: the cap must trip + // (stall set, heartbeat frozen) BEFORE the agent archives. + it('agent archives the held message itself → stall clears, heartbeat resumes', async () => { + writeFileSync(statusFile, 'available\n'); + const oldT = new Date(Date.now() - 60_000); + utimesSync(statusFile, oldT, oldT); + + // The pane NEVER goes idle. Recovery must come from the message + // ceasing to need delivery, not from a delivery succeeding. + let n = 0; + const peeker = makePeeker(() => `frame ${n++}`); + let pending = true; // message is in the inbox + let err = ''; + const r = startDing({ + st: fake.st, + ptySend: sender.send, + identity: asIdentity(ID), + paneGuard: true, + ptyPeek: peeker.peek, + peekDiffMs: 1, + holdRetryMs: 15, + maxHolds: 1, + statusRefreshIntervalMs: 20, + intervalMs: 10, + messagePending: () => pending, + stderr: (s) => { + err += s; + }, + }); + fake.setMessage('1714826789010-aaaaaa.md', { from: 'alice' }); + fake.pushEvent('1714826789010-aaaaaa.md'); + + // Precondition: the cap trips and the heartbeat freezes FIRST. + await waitFor(() => err.includes('DELIVERY STALLED')); + expect(err).toContain('DELIVERY STALLED'); + const mtimeAtStall = statSync(statusFile).mtimeMs; + await new Promise((res) => setTimeout(res, 100)); // several ticks + expect(statSync(statusFile).mtimeMs).toBe(mtimeAtStall); // suspended + + // NOW the agent reads + archives the message itself. + pending = false; + + // The stall's cause is gone, so the stall must go with it — even + // though the pane is still busy and nothing was ever delivered. + await waitFor(() => statSync(statusFile).mtimeMs > mtimeAtStall); + expect(statSync(statusFile).mtimeMs).toBeGreaterThan(mtimeAtStall); + expect(err).toContain('delivery recovered'); + expect(sender.calls()).toHaveLength(0); // never delivered — correct + + r.ac.abort(); + await r.done; + }); + + it('one of two held messages archived → stall PERSISTS (still undeliverable)', async () => { + // Guard against over-clearing: the stall is per-daemon, so clearing + // it the moment ANY single message is archived would resume the + // heartbeat while a second message is still genuinely undeliverable + // — re-introducing exactly the unearned liveness #106 exists to + // prevent. The stall must track "no message remains undeliverable", + // not "some message stopped needing delivery". + writeFileSync(statusFile, 'available\n'); + const oldT = new Date(Date.now() - 60_000); + utimesSync(statusFile, oldT, oldT); + + let n = 0; + const peeker = makePeeker(() => `frame ${n++}`); // never static + const archived = new Set(); + let err = ''; + const r = startDing({ + st: fake.st, + ptySend: sender.send, + identity: asIdentity(ID), + paneGuard: true, + ptyPeek: peeker.peek, + peekDiffMs: 1, + holdRetryMs: 15, + maxHolds: 1, + statusRefreshIntervalMs: 20, + intervalMs: 10, + messagePending: (f) => !archived.has(String(f)), + stderr: (s) => { + err += s; + }, + }); + fake.setMessage('1714826789010-aaaaaa.md', { from: 'alice' }); + fake.pushEvent('1714826789010-aaaaaa.md'); + fake.setMessage('1714826789011-bbbbbb.md', { from: 'carol' }); + fake.pushEvent('1714826789011-bbbbbb.md'); + + await waitFor(() => err.includes('DELIVERY STALLED')); + const mtimeAtStall = statSync(statusFile).mtimeMs; + + // The agent archives only the FIRST message. The second is still + // held on a busy pane — still undeliverable. + archived.add('1714826789010-aaaaaa.md'); + + await new Promise((res) => setTimeout(res, 150)); // many refresh ticks + expect(statSync(statusFile).mtimeMs).toBe(mtimeAtStall); // still suspended + expect(err).not.toContain('delivery recovered'); + + // Archiving the last one clears it. + archived.add('1714826789011-bbbbbb.md'); + await waitFor(() => statSync(statusFile).mtimeMs > mtimeAtStall); + expect(statSync(statusFile).mtimeMs).toBeGreaterThan(mtimeAtStall); + expect(err).toContain('delivery recovered'); + + r.ac.abort(); + await r.done; + }); + + it('archived while held on a BUSY identity → stall still clears', async () => { + // The residual path: the drain loop's own `stillInInbox` check sits + // AFTER the busy/dnd suppress-return, so a busy agent's archived + // message would never be pruned and the stall would outlive it. + // The prune therefore runs before the status gate. + writeFileSync(statusFile, 'available\n'); + const oldT = new Date(Date.now() - 60_000); + utimesSync(statusFile, oldT, oldT); + + let n = 0; + const peeker = makePeeker(() => `frame ${n++}`); + let pending = true; + let err = ''; + const r = startDing({ + st: fake.st, + ptySend: sender.send, + identity: asIdentity(ID), + paneGuard: true, + ptyPeek: peeker.peek, + peekDiffMs: 1, + holdRetryMs: 15, + maxHolds: 1, + statusRefreshIntervalMs: 20, + intervalMs: 10, + messagePending: () => pending, + stderr: (s) => { + err += s; + }, + }); + fake.setMessage('1714826789010-aaaaaa.md', { from: 'alice' }); + fake.pushEvent('1714826789010-aaaaaa.md'); + + await waitFor(() => err.includes('DELIVERY STALLED')); + const mtimeAtStall = statSync(statusFile).mtimeMs; + + // Agent marks itself busy AND archives its own mail. + fake.setStatus('busy'); + pending = false; + + await waitFor(() => statSync(statusFile).mtimeMs > mtimeAtStall); + expect(statSync(statusFile).mtimeMs).toBeGreaterThan(mtimeAtStall); + expect(err).toContain('delivery recovered'); + + r.ac.abort(); + await r.done; + }); + + it('held but still UNDER the cap → heartbeat keeps running', async () => { + // Guard against over-suppression: a brief hold on a momentarily-busy + // pane is normal operation, not a stall. Liveness stays earned. + writeFileSync(statusFile, 'available\n'); + const oldT = new Date(Date.now() - 60_000); + utimesSync(statusFile, oldT, oldT); + const mtimeBefore = statSync(statusFile).mtimeMs; + + let n = 0; + const peeker = makePeeker(() => `frame ${n++}`); + let err = ''; + const r = startDing({ + st: fake.st, + ptySend: sender.send, + identity: asIdentity(ID), + paneGuard: true, + ptyPeek: peeker.peek, + peekDiffMs: 1, + holdRetryMs: 10_000, // no retry inside the window → holds stays 1 + maxHolds: 50, // cap far away + statusRefreshIntervalMs: 20, + intervalMs: 10, + stderr: (s) => { + err += s; + }, + }); + fake.setMessage('1714826789010-aaaaaa.md', { from: 'alice' }); + fake.pushEvent('1714826789010-aaaaaa.md'); + + await waitFor(() => statSync(statusFile).mtimeMs > mtimeBefore); + expect(statSync(statusFile).mtimeMs).toBeGreaterThan(mtimeBefore); + expect(err).not.toContain('DELIVERY STALLED'); + + r.ac.abort(); + await r.done; + }); +}); diff --git a/tests/unit/status-staleness.test.ts b/tests/unit/status-staleness.test.ts index 9760638..a8cd84b 100644 --- a/tests/unit/status-staleness.test.ts +++ b/tests/unit/status-staleness.test.ts @@ -16,8 +16,16 @@ import { tmpdir } from 'node:os'; import { join } from 'node:path'; import { afterEach, beforeEach, describe, expect, it } from 'vitest'; -import { STATUS_STALE_MS } from '../../src/common.ts'; -import { readIdentityStatus } from '../../src/commands/status.ts'; +import { + LIVENESS_HEARTBEAT_MS, + STATUS_LIVENESS_MS, + STATUS_REFRESH_MS, + STATUS_STALE_MS, +} from '../../src/common.ts'; +import { + readIdentityLiveness, + readIdentityStatus, +} from '../../src/commands/status.ts'; let scratch: string; let stRoot: string; @@ -88,3 +96,110 @@ describe('readIdentityStatus — mtime staleness', () => { expect(readIdentityStatus('alice', stRoot)).toBe('unknown'); }); }); + +// ─── #102: the shared freshness contract ─────────────────────────────── +// +// `st agents` said `available` at the same instant `convoy ls --tree` +// said `DEAD (status stale 3m ago)`. The premise in the issue — that +// `st agents` had NO freshness window — turned out to be wrong: it has +// one, STATUS_STALE_MS, but that window answers "do we still trust this +// value?" (15 min, sized for the MCP server's 5-min refresh), not "is +// this agent live?" (~2 min, sized for the ding's 30s heartbeat). +// +// So the divergence was a threshold mismatch, not a missing check. +// `readIdentityLiveness` exposes BOTH windows through one reader so +// consumers stop each inventing their own. +describe('readIdentityLiveness — shared freshness contract', () => { + it('fresh file → live, recorded value preserved, small age', () => { + writeStatus('alice', 'available'); + const l = readIdentityLiveness('alice', stRoot); + expect(l.status).toBe('available'); + expect(l.recorded).toBe('available'); + expect(l.live).toBe(true); + expect(l.ageMs).toBeLessThan(5_000); + }); + + it('the reported case: 3m old reads NOT live while status stays `available`', () => { + // This is exactly the disagreement from the issue. The trust window + // (15 min) is untouched, so `status` is still `available` — but + // `live` is false, which is what convoy was reporting. + const path = writeStatus('alice', 'available'); + backdate(path, 3 * 60_000); + const l = readIdentityLiveness('alice', stRoot); + expect(l.status).toBe('available'); // trust window: unchanged + expect(l.live).toBe(false); // liveness window: not demonstrably up + expect(l.ageMs).toBeGreaterThan(2.5 * 60_000); + }); + + it('inside the liveness window → live', () => { + const path = writeStatus('alice', 'busy'); + backdate(path, STATUS_LIVENESS_MS - 30_000); + expect(readIdentityLiveness('alice', stRoot).live).toBe(true); + }); + + it('past the liveness window but inside trust → live=false, status kept', () => { + const path = writeStatus('alice', 'busy'); + backdate(path, STATUS_LIVENESS_MS + 30_000); + const l = readIdentityLiveness('alice', stRoot); + expect(l.live).toBe(false); + expect(l.status).toBe('busy'); + }); + + it('stale-but-was-`busy` stays distinguishable from clean `offline`', () => { + // The debugging signal the issue asked us not to collapse: an agent + // that died mid-work is not the same as one that shut down. + const busyPath = writeStatus('alice', 'busy'); + backdate(busyPath, STATUS_STALE_MS + 60_000); + mkdirSync(join(stRoot, 'carol'), { recursive: true }); + const offPath = writeStatus('carol', 'offline'); + backdate(offPath, STATUS_STALE_MS + 60_000); + + const wasBusy = readIdentityLiveness('alice', stRoot); + const wasOffline = readIdentityLiveness('carol', stRoot); + + // Both derive to `unknown` (the trust window is blown) … + expect(wasBusy.status).toBe('unknown'); + expect(wasOffline.status).toBe('unknown'); + // … but `recorded` keeps them apart. + expect(wasBusy.recorded).toBe('busy'); + expect(wasOffline.recorded).toBe('offline'); + }); + + it('missing file → not live, no age, no recorded value', () => { + // Distinct from a recorded `offline`: nothing was ever claimed. + const l = readIdentityLiveness('alice', stRoot); + expect(l.status).toBe('offline'); + expect(l.live).toBe(false); + expect(l.ageMs).toBeNull(); + expect(l.recorded).toBeNull(); + }); + + it('corrupt contents → recorded is null, status falls back to `offline`', () => { + writeStatus('alice', 'garbage-value'); + const l = readIdentityLiveness('alice', stRoot); + expect(l.status).toBe('offline'); + expect(l.recorded).toBeNull(); + expect(l.live).toBe(true); // the FILE is fresh; its contents are not usable + }); + + it('livenessMs is overridable so a consumer can be stricter', () => { + const path = writeStatus('alice', 'available'); + backdate(path, 30_000); + expect(readIdentityLiveness('alice', stRoot).live).toBe(true); + expect( + readIdentityLiveness('alice', stRoot, { livenessMs: 10_000 }).live + ).toBe(false); + }); + + it('the two windows are deliberately different (regression guard)', () => { + // Tightening STATUS_STALE_MS down to the liveness window would flap + // MCP-refreshed agents (5-min refresh) into `unknown` between every + // refresh. Keep them apart. + expect(STATUS_LIVENESS_MS).toBeLessThan(STATUS_STALE_MS); + expect(STATUS_REFRESH_MS).toBeLessThan(STATUS_STALE_MS); + // The liveness window must clear several ding heartbeats. + expect(STATUS_LIVENESS_MS).toBeGreaterThanOrEqual( + 3 * LIVENESS_HEARTBEAT_MS + ); + }); +});