-
Notifications
You must be signed in to change notification settings - Fork 4
fix(t2): stop delivery receipts asserting outcomes nobody observed #483
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -260,14 +260,25 @@ export interface AgentDeliveryReceipt { | |
| composer_accepted?: boolean; | ||
| /** Hard deadline for background verify; ISO timestamp. */ | ||
| verify_deadline_at?: string | null; | ||
| /** | ||
| * Hard deadline for a retryable requeue; ISO timestamp. Set on the first | ||
| * retryable refusal so a target that never becomes interactive resolves | ||
| * instead of leaving the caller an open queue forever (#467). | ||
| */ | ||
| queue_deadline_at?: string | null; | ||
| ticket_filed?: boolean; | ||
| /** Whether the local evidence ticket was escalated to the issue tracker. */ | ||
| ticket_escalated?: boolean; | ||
| /** Why escalation was declined, when it was. */ | ||
| ticket_escalation_declined_reason?: string | null; | ||
| /** Consecutive verifier observations that the target agent is missing. */ | ||
| verify_miss_count?: number; | ||
| /** Last time background verify actually read the target surface. */ | ||
| verify_last_attempt_at?: string | null; | ||
| } | ||
|
|
||
| export const DEFAULT_DELIVERY_VERIFY_DEADLINE_MS = 10 * 60 * 1000; | ||
| export const DEFAULT_DELIVERY_QUEUE_DEADLINE_MS = 10 * 60 * 1000; | ||
| export const DELIVERY_TARGET_GONE_CONFIRM_MISSES = 3; | ||
| const DELIVERY_WAIT_POLL_MS = 100; | ||
|
|
||
|
|
@@ -664,6 +675,7 @@ export interface AgentEngineOptions { | |
| deliveryVerifyTimeoutMs?: number; | ||
| /** How long a pending_verify delivery may stay nonterminal before failed_confirmed. */ | ||
| deliveryVerifyDeadlineMs?: number; | ||
| deliveryQueueDeadlineMs?: number; | ||
| /** | ||
| * Local evidence-ticket directory. Omitted/null disables tickets so bare | ||
| * construction never writes ~/.cmuxlayer/tickets or calls gh. Production | ||
|
|
@@ -1546,6 +1558,7 @@ export class AgentEngine { | |
| private deliverySubmitTimeoutMs: number; | ||
| private deliveryVerifyTimeoutMs: number; | ||
| private deliveryVerifyDeadlineMs: number; | ||
| private deliveryQueueDeadlineMs: number; | ||
| private deliveryTicketDir: string | null; | ||
| private deliveryIssueFiler: DeliveryIssueFiler | null = null; | ||
| private autoReviveBackoffBaseMs: number; | ||
|
|
@@ -1578,6 +1591,10 @@ export class AgentEngine { | |
| 1, | ||
| opts?.deliveryVerifyDeadlineMs ?? DEFAULT_DELIVERY_VERIFY_DEADLINE_MS, | ||
| ); | ||
| this.deliveryQueueDeadlineMs = Math.max( | ||
| 1, | ||
| opts?.deliveryQueueDeadlineMs ?? DEFAULT_DELIVERY_QUEUE_DEADLINE_MS, | ||
| ); | ||
| this.deliveryTicketDir = opts?.deliveryTicketDir ?? null; | ||
| this.deliveryIssueFiler = opts?.deliveryIssueFiler ?? null; | ||
| this.deliveryVerifier = opts?.deliveryVerifier ?? null; | ||
|
|
@@ -6885,36 +6902,34 @@ export class AgentEngine { | |
| let snapshot: DeliveryVerifySnapshot | null | undefined; | ||
| if (this.deliverySnapshotReader) { | ||
| if (!snapshots.has(snapshotKey)) { | ||
| // AIDEV-NOTE (T2 #450): the snapshot read must be inside the | ||
| // hang guard, not before it. SF8 hoisted the surface read out of | ||
| // the verifier and awaited it OUTSIDE SF7's race; the CLI | ||
| // fallback path has no subprocess timeout, so one wedged `cmux` | ||
| // held deliveryVerifyInFlight forever and every later verify | ||
| // pass short-circuited -- exactly the stall SF7 exists to | ||
| // prevent. A timed-out read yields a null snapshot, which the | ||
| // verifier already treats as "no evidence, stay pending". | ||
| snapshots.set( | ||
| snapshotKey, | ||
| await this.deliverySnapshotReader(receipt), | ||
| await this.withDeliveryVerifyTimeout( | ||
| this.deliverySnapshotReader(receipt), | ||
| "Delivery snapshot read", | ||
| ).catch(() => null), | ||
| ); | ||
| } | ||
| snapshot = snapshots.get(snapshotKey) ?? null; | ||
| } | ||
| let timeout: ReturnType<typeof setTimeout> | null = null; | ||
| try { | ||
| observation = await Promise.race([ | ||
| observation = await this.withDeliveryVerifyTimeout( | ||
| this.deliveryVerifier(receipt, snapshot), | ||
| new Promise<never>((_resolve, reject) => { | ||
| timeout = setTimeout( | ||
| () => | ||
| reject( | ||
| new Error( | ||
| `Delivery verify timed out after ${this.deliveryVerifyTimeoutMs}ms`, | ||
| ), | ||
| ), | ||
| this.deliveryVerifyTimeoutMs, | ||
| ); | ||
| }), | ||
| ]); | ||
| "Delivery verify", | ||
| ); | ||
| } catch (error) { | ||
| observation = { | ||
| outcome: "pending", | ||
| reason: error instanceof Error ? error.message : String(error), | ||
| }; | ||
| } finally { | ||
| if (timeout) clearTimeout(timeout); | ||
| } | ||
| receipt.verify_last_attempt_at = new Date().toISOString(); | ||
| this.persistDeliveryReceipts(); | ||
|
|
@@ -6964,6 +6979,30 @@ export class AgentEngine { | |
| } | ||
| } | ||
|
|
||
| /** Bound one delivery-verify side quest to the verify timeout. */ | ||
| private withDeliveryVerifyTimeout<T>( | ||
| work: Promise<T>, | ||
| label: string, | ||
| ): Promise<T> { | ||
| let timeout: ReturnType<typeof setTimeout> | null = null; | ||
| return Promise.race([ | ||
| work, | ||
| new Promise<never>((_resolve, reject) => { | ||
| timeout = setTimeout( | ||
| () => | ||
| reject( | ||
| new Error( | ||
| `${label} timed out after ${this.deliveryVerifyTimeoutMs}ms`, | ||
| ), | ||
| ), | ||
| this.deliveryVerifyTimeoutMs, | ||
| ); | ||
| }), | ||
| ]).finally(() => { | ||
| if (timeout) clearTimeout(timeout); | ||
| }); | ||
| } | ||
|
|
||
| private verifyReadIntervalMs( | ||
| receipt: AgentDeliveryReceipt, | ||
| now: number, | ||
|
|
@@ -6994,6 +7033,35 @@ export class AgentEngine { | |
| return since > 0 && since < this.verifyReadIntervalMs(receipt, now); | ||
| } | ||
|
|
||
| /** | ||
| * A confirmed-failure verdict is worth an issue only when something was | ||
| * actually observed to go wrong with the message. | ||
| * | ||
| * AIDEV-NOTE (T2 #471/#443): `verify_deadline_elapsed` means the ENGINE | ||
| * stopped looking, and `target_gone` means there was nothing left to look | ||
| * at. Neither is evidence the message was lost, and auto-filing them | ||
| * produced issues #471 and #443 -- tracker noise describing cmuxlayer's own | ||
| * timers, not a defect. The local evidence ticket is still written either | ||
| * way, so the verdict keeps citing its evidence; only the escalation stops. | ||
| */ | ||
| private deliveryFailureEscalationDecline( | ||
| reason: string, | ||
| ): string | null { | ||
| if (reason === "verify_deadline_elapsed") { | ||
| return ( | ||
| "background verify ran out of deadline before observing an outcome; " + | ||
| "no evidence the message was lost" | ||
| ); | ||
| } | ||
| if (reason === "target_gone") { | ||
| return ( | ||
| "the target agent disappeared before an outcome could be observed; " + | ||
| "no evidence the message was lost" | ||
| ); | ||
| } | ||
| return null; | ||
| } | ||
|
|
||
| private async fileConfirmedFailureTicket( | ||
| receipt: AgentDeliveryReceipt, | ||
| reason: string, | ||
|
|
@@ -7028,13 +7096,39 @@ export class AgentEngine { | |
| dir: ticketDir, | ||
| }); | ||
| receipt.ticket_filed = true; | ||
| this.persistDeliveryReceipts(); | ||
| if (!written.created) return; | ||
| if (!this.deliveryIssueFiler) return; | ||
|
|
||
| // AIDEV-NOTE (T2 B2): both fields are written from the SAME resolved | ||
| // outcome, at every exit, and never before the escalation is known. | ||
| // Stamping `escalated: true` up front and then returning early -- deduped | ||
| // signature, no filer configured, filer threw -- left receipts asserting | ||
| // an escalation that never happened. That is this lane's own disease: a | ||
| // receipt reporting something the engine did not observe. | ||
| const settleEscalation = (declined: string | null): void => { | ||
| receipt.ticket_escalated = declined === null; | ||
| receipt.ticket_escalation_declined_reason = declined; | ||
| this.persistDeliveryReceipts(); | ||
| }; | ||
|
|
||
| const declineReason = this.deliveryFailureEscalationDecline(reason); | ||
| if (declineReason !== null) return settleEscalation(declineReason); | ||
| if (!written.created) { | ||
| return settleEscalation( | ||
| "an issue for this failure signature was already filed; " + | ||
| "this occurrence was appended to the existing ticket", | ||
| ); | ||
| } | ||
| if (!this.deliveryIssueFiler) { | ||
| return settleEscalation("no issue filer is configured"); | ||
| } | ||
| try { | ||
| await this.deliveryIssueFiler(ticket); | ||
| } catch { | ||
| // Local ticket is authoritative; GitHub is best-effort. | ||
| settleEscalation(null); | ||
| } catch (error) { | ||
| // Local ticket is authoritative; GitHub is best-effort -- but the | ||
| // receipt must say the escalation did not land. | ||
| settleEscalation( | ||
| `issue filer failed: ${error instanceof Error ? error.message : String(error)}`, | ||
| ); | ||
|
Comment on lines
7123
to
+7131
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟡 Medium A successful try {
await this.deliveryIssueFiler(ticket);
- settleEscalation(null);
} catch (error) {
// Local ticket is authoritative; GitHub is best-effort -- but the
// receipt must say the escalation did not land.
- settleEscalation(
+ return settleEscalation(
`issue filer failed: ${error instanceof Error ? error.message : String(error)}`,
);
}
+ settleEscalation(null);🚀 Reply "fix it for me" or copy this AI Prompt for your agent: |
||
| } | ||
| } | ||
|
|
||
|
|
@@ -7055,9 +7149,36 @@ export class AgentEngine { | |
| this.appendDeliveryReceiptEventBestEffort(receipt); | ||
| continue; | ||
| } | ||
| // AIDEV-NOTE (T2 N1): a paused target deliberately does NOT age out. | ||
| // #467's bounded lifetime exists for a target that is failing to | ||
| // become interactive on its own; pausing is a human's resumable act, | ||
| // and expiring queued work under it would discard the message the | ||
| // pause was protecting. The receipt stays nonterminal, and the | ||
| // paused-target WARNING already tells the caller it is not delivered. | ||
| if (agent.paused === true) { | ||
| continue; | ||
| } | ||
| // AIDEV-NOTE (T2 #467): a retryable refusal is nonterminal, but it is | ||
| // not unbounded. Without this, a target stuck `booting` retried behind | ||
| // a 30s-capped backoff forever and the caller's receipt never resolved | ||
| // -- a lead could wait on it indefinitely. The lifetime is stamped on | ||
| // the first retryable requeue below; when it elapses the caller gets a | ||
| // terminal answer that cites the gate reason that kept refusing. | ||
| if ( | ||
| receipt.queue_deadline_at && | ||
| Date.now() >= Date.parse(receipt.queue_deadline_at) | ||
| ) { | ||
| const gateReason = receipt.error ?? "no gate reason recorded"; | ||
| receipt.delivery_state = "failed_confirmed"; | ||
| receipt.terminal = true; | ||
| receipt.submit_verified = false; | ||
| receipt.resolved_at = new Date().toISOString(); | ||
| receipt.next_attempt_at = null; | ||
| receipt.error = `queue_deadline_elapsed after ${receipt.retry_count} retryable refusals; last gate reason: ${gateReason}`; | ||
| this.persistDeliveryReceipts(); | ||
| this.appendDeliveryReceiptEventBestEffort(receipt); | ||
| continue; | ||
| } | ||
|
Comment on lines
+7161
to
+7181
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🎯 Functional Correctness | 🟠 Major | ⚡ Quick win Expire paused queued deliveries. The preceding Assign a queue deadline when creating a queued receipt, and evaluate expiry before the paused-target skip. Add a paused-target expiry test. 🤖 Prompt for AI Agents |
||
| if ( | ||
| receipt.next_attempt_at && | ||
| Date.parse(receipt.next_attempt_at) > Date.now() | ||
|
|
@@ -7123,6 +7244,9 @@ export class AgentEngine { | |
| if (error instanceof RetryableDeliveryError) { | ||
| receipt.submission_started_at = null; | ||
| receipt.retry_count += 1; | ||
| receipt.queue_deadline_at ??= new Date( | ||
| Date.now() + this.deliveryQueueDeadlineMs, | ||
| ).toISOString(); | ||
|
Comment on lines
+7247
to
+7249
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🎯 Functional Correctness | 🟠 Major | ⚡ Quick win Preserve the queue deadline across restart. Persisted retryable receipts from before this change have no Backfill missing deadlines during 🤖 Prompt for AI Agents |
||
| const backoffMs = Math.min( | ||
| 30_000, | ||
| 250 * 2 ** Math.min(receipt.retry_count - 1, 16), | ||
|
|
||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -28,6 +28,16 @@ import { parseCmuxStatusFrame } from "./cmux-status-frame.js"; | |
| import { isCmuxAccessControlDenied } from "./cmux-access-control.js"; | ||
|
|
||
| const execFileAsync = promisify(execFile); | ||
| /** | ||
| * Hard ceiling on one CLI-fallback `cmux` invocation. | ||
| * | ||
| * AIDEV-NOTE (T2 #450): the socket transport is bounded by its own | ||
| * REQUEST_TIMEOUT_MS, but this fallback had none -- a wedged `cmux` | ||
| * subprocess held its caller (notably the delivery snapshot read) forever. | ||
| * Matches the socket client's 10s budget so neither transport can outlast the | ||
| * other. | ||
| */ | ||
| export const CMUX_CLI_EXEC_TIMEOUT_MS = 10_000; | ||
| const STANDARD_BUNDLED_CMUX = | ||
| "/Applications/cmux.app/Contents/Resources/bin/cmux"; | ||
|
|
||
|
|
@@ -55,6 +65,8 @@ interface CmuxClientOptions { | |
| bin?: string; | ||
| env?: NodeJS.ProcessEnv; | ||
| existsSync?: (path: string) => boolean; | ||
| /** Hard ceiling on one CLI-fallback exec; defaults to CMUX_CLI_EXEC_TIMEOUT_MS. */ | ||
| execTimeoutMs?: number; | ||
| } | ||
|
|
||
| interface CmuxIdentifyResult { | ||
|
|
@@ -75,13 +87,18 @@ export class CmuxClient { | |
| private bin?: string; | ||
| private env?: NodeJS.ProcessEnv; | ||
| private existsSync: (path: string) => boolean; | ||
| private execTimeoutMs: number; | ||
| private observerTransportGeneration = 0; | ||
|
|
||
| constructor(opts?: CmuxClientOptions) { | ||
| this.exec = opts?.exec; | ||
| this.bin = opts?.bin; | ||
| this.env = opts?.env; | ||
| this.existsSync = opts?.existsSync ?? fs.existsSync; | ||
| this.execTimeoutMs = Math.max( | ||
| 1, | ||
| opts?.execTimeoutMs ?? CMUX_CLI_EXEC_TIMEOUT_MS, | ||
| ); | ||
|
Comment on lines
+98
to
+101
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🩺 Stability & Availability | 🟡 Minor | ⚡ Quick win 🧩 Analysis chain🏁 Script executed: #!/bin/bash
set -eu
printf '%s\n' '--- src/cmux-client.ts ---'
sed -n '1,190p' src/cmux-client.ts
printf '%s\n' '--- CmuxClient construction and injected executor references ---'
rg -n -C 3 'new CmuxClient|CmuxClient|execTimeoutMs|ExecFn|execFileAsync' --glob '!node_modules' --glob '!dist' --glob '!build' .Repository: EtanHey/cmuxlayer Length of output: 50374 🏁 Script executed: #!/bin/bash
set -eu
printf '%s\n' '--- timeout-related tests and option plumbing ---'
rg -n -C 4 'execTimeoutMs|CMUX_CLI_EXEC_TIMEOUT_MS|timeout.*exec|exec.*timeout' src tests README.md package.json 2>/dev/null || true
printf '%s\n' '--- factory option construction ---'
sed -n '20,115p' src/cmux-client-factory.ts
sed -n '3268,3300p' src/server.ts
printf '%s\n' '--- injected executor declarations and call sites outside tests ---'
rg -n -C 2 'exec\?: ExecFn|opts\?\.exec|new CmuxClient\(\{|createServer\(\{' src --glob '*.ts'Repository: EtanHey/cmuxlayer Length of output: 13693 🌐 Web query:
💡 Result: In Node.js, the Citations:
🏁 Script executed: #!/bin/bash
set -eu
node - <<'JS'
const { execFile } = require("node:child_process");
console.log("node", process.version);
for (const value of [NaN, Infinity, -Infinity, -1, 0, 1, 150]) {
await new Promise((resolve) => {
const started = Date.now();
const child = execFile(
process.execPath,
["-e", "setTimeout(() => process.exit(0), 50)"],
{ timeout: value },
(error) => {
console.log(JSON.stringify({
input: String(value),
mathMax: Math.max(1, value),
errorCode: error?.code ?? null,
errorName: error?.name ?? null,
timedOut: error?.killed === true || error?.signal === "SIGTERM",
elapsedMs: Date.now() - started,
}));
resolve();
},
);
child.on("error", () => {});
});
}
JSRepository: EtanHey/cmuxlayer Length of output: 1005 🏁 Script executed: #!/bin/bash
set -eu
node --input-type=module - <<'JS'
import { execFile } from "node:child_process";
console.log("node", process.version);
for (const value of [NaN, Infinity, -Infinity, -1, 0, 1, 150]) {
await new Promise((resolve) => {
const started = Date.now();
const child = execFile(
process.execPath,
["-e", "setTimeout(() => process.exit(0), 50)"],
{ timeout: value },
(error) => {
console.log(JSON.stringify({
input: String(value),
mathMax: Math.max(1, value),
errorCode: error?.code ?? null,
errorName: error?.name ?? null,
timedOut: error?.killed === true || error?.signal === "SIGTERM",
elapsedMs: Date.now() - started,
}));
resolve();
},
);
child.on("error", () => {});
});
}
JSRepository: EtanHey/cmuxlayer Length of output: 1037 🏁 Script executed: #!/bin/bash
set -eu
node --input-type=module - <<'JS'
import { execFile } from "node:child_process";
console.log("node", process.version);
for (const value of [NaN, Infinity, -Infinity, -1, 0, 1, 1.5, 150]) {
const result = {
input: String(value),
mathMax: Math.max(1, value),
};
try {
await new Promise((resolve, reject) => {
const child = execFile(
process.execPath,
["-e", "setTimeout(() => process.exit(0), 50)"],
{ timeout: value },
(error) => {
result.errorCode = error?.code ?? null;
result.errorName = error?.name ?? null;
result.timedOut =
error?.killed === true || error?.signal === "SIGTERM";
resolve();
},
);
child.on("error", reject);
});
} catch (error) {
result.errorCode = error?.code ?? null;
result.errorName = error?.name ?? null;
result.threwSynchronously = true;
}
console.log(JSON.stringify(result));
}
JSRepository: EtanHey/cmuxlayer Length of output: 974 Validate
🤖 Prompt for AI Agents |
||
| } | ||
|
|
||
| setEnv(env: NodeJS.ProcessEnv | undefined): void { | ||
|
|
@@ -121,6 +138,10 @@ export class CmuxClient { | |
| ) | ||
| : await execFileAsync(bin, cliArgs, { | ||
| ...(env ? { env } : {}), | ||
| timeout: this.execTimeoutMs, | ||
|
coderabbitai[bot] marked this conversation as resolved.
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟡 Medium When 🚀 Reply "fix it for me" or copy this AI Prompt for your agent:There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟠 High
🚀 Reply "fix it for me" or copy this AI Prompt for your agent: |
||
| // N2: a subprocess that ignores SIGTERM would still hang the | ||
| // promise the timeout exists to bound. | ||
| killSignal: "SIGKILL", | ||
| }); | ||
| return stdout; | ||
| } catch (error) { | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
🟡 Medium
src/agent-engine.ts:7115A deduplicated local ticket is treated as proof that external escalation already happened, so a later occurrence is never sent to
deliveryIssueFilerand is recorded asticket_escalated: falseeven when the earlier filer was absent, failed, or succeeded before its receipt update persisted. Track durable external-escalation state separately from local-ticket creation instead of inferring it fromwritten.created.🚀 Reply "fix it for me" or copy this AI Prompt for your agent: