diff --git a/server/src/services/recovery/service.ts b/server/src/services/recovery/service.ts index b98c428a..17459125 100644 --- a/server/src/services/recovery/service.ts +++ b/server/src/services/recovery/service.ts @@ -68,7 +68,89 @@ const UNSUCCESSFUL_HEARTBEAT_RUN_TERMINAL_STATUSES = ["failed", "cancelled", "ti export const ACTIVE_RUN_OUTPUT_SUSPICION_THRESHOLD_MS = 60 * 60 * 1000; export const ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS = 4 * 60 * 60 * 1000; export const ACTIVE_RUN_OUTPUT_CONTINUE_REARM_MS = 30 * 60 * 1000; +// ORA-289: runs younger than this cannot have legitimately produced output yet. +// Stale-run evaluation ignores them regardless of log size, so the 0-byte / +// <200-byte log heuristic no longer fires class-1 false positives. +export const ACTIVE_RUN_OUTPUT_MIN_AGE_MS = 30 * 1000; +// ORA-289: a run older than this with a 0-byte / <200-byte log and no spawn +// PID or no in-memory process handle is treated as a class-2 stall / zombie +// even before the general suspicion threshold (60m) trips. Lets the watchdog +// surface the ORA-284 / ORA-275 / ORA-276 family of stalls at the operator's +// desired SLA instead of waiting an hour. +export const ACTIVE_RUN_OUTPUT_LIKELY_ZOMBIE_THRESHOLD_MS = 5 * 60 * 1000; +// ORA-289: any log strictly below this byte count is treated as "near-empty" +// for the likely-zombie/stall detection branch. Matches the bootstrap-only +// `<200-byte` heuristic called out in the issue evidence. +export const ACTIVE_RUN_OUTPUT_NEAR_EMPTY_BYTES = 200; const ACTIVE_RUN_OUTPUT_EVIDENCE_TAIL_BYTES = 8 * 1024; + +export type StaleRunEvaluationDecision = + | { + kind: "evaluate"; + level: "suspicious" | "critical"; + reason: "above_suspicion_threshold" | "above_critical_threshold" | "likely_zombie_or_stall"; + elapsedMs: number; + wallClockSec: number; + } + | { + kind: "skip"; + reason: "no_silence_anchor" | "too_young" | "below_threshold"; + elapsedMs: number | null; + wallClockSec: number | null; + }; + +export type StaleRunEvaluationInput = { + silenceAgeMs: number | null; + logBytes: number | null; + hasSpawnPid: boolean; + hasInMemoryHandle: boolean; +}; + +export function decideStaleRunEvaluation(input: StaleRunEvaluationInput): StaleRunEvaluationDecision { + if (input.silenceAgeMs == null) { + return { kind: "skip", reason: "no_silence_anchor", elapsedMs: null, wallClockSec: null }; + } + const elapsedMs = Math.max(0, Math.floor(input.silenceAgeMs)); + const wallClockSec = Math.floor(elapsedMs / 1000); + if (elapsedMs < ACTIVE_RUN_OUTPUT_MIN_AGE_MS) { + return { kind: "skip", reason: "too_young", elapsedMs, wallClockSec }; + } + const logBytes = input.logBytes ?? 0; + const nearEmpty = logBytes < ACTIVE_RUN_OUTPUT_NEAR_EMPTY_BYTES; + const noProcessAnchor = !input.hasSpawnPid || !input.hasInMemoryHandle; + if ( + elapsedMs >= ACTIVE_RUN_OUTPUT_LIKELY_ZOMBIE_THRESHOLD_MS && + nearEmpty && + noProcessAnchor + ) { + return { + kind: "evaluate", + level: "suspicious", + reason: "likely_zombie_or_stall", + elapsedMs, + wallClockSec, + }; + } + if (elapsedMs >= ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS) { + return { + kind: "evaluate", + level: "critical", + reason: "above_critical_threshold", + elapsedMs, + wallClockSec, + }; + } + if (elapsedMs >= ACTIVE_RUN_OUTPUT_SUSPICION_THRESHOLD_MS) { + return { + kind: "evaluate", + level: "suspicious", + reason: "above_suspicion_threshold", + elapsedMs, + wallClockSec, + }; + } + return { kind: "skip", reason: "below_threshold", elapsedMs, wallClockSec }; +} const STRANDED_ISSUE_RECOVERY_ORIGIN_KIND = RECOVERY_ORIGIN_KINDS.strandedIssueRecovery; const STALE_ACTIVE_RUN_EVALUATION_ORIGIN_KIND = RECOVERY_ORIGIN_KINDS.staleActiveRunEvaluation; const DEFERRED_WAKE_CONTEXT_KEY = "_paperclipWakeContext"; @@ -1446,6 +1528,7 @@ export function recoveryService(db: Db, deps: { enqueueWakeup: RecoveryWakeup }) evidence: Awaited>; level: "suspicious" | "critical"; now: Date; + decision?: StaleRunEvaluationDecision; }) { const sourceIssue = input.sourceIssue ? issueUiLink({ identifier: input.sourceIssue.identifier, id: input.sourceIssue.id }, input.prefix) @@ -1465,6 +1548,18 @@ export function recoveryService(db: Db, deps: { enqueueWakeup: RecoveryWakeup }) `- ${issueUiLink({ identifier: issue.identifier, id: issue.id }, input.prefix)} \`${issue.status}\`: ${issue.title}`, ).join("\n") : "- none detected"; + const wallClockLine = + input.decision && input.decision.kind === "evaluate" + ? `- wallClockSec: ${input.decision.wallClockSec}` + : `- wallClockSec: ${input.evidence.silenceAgeMs == null ? "unknown" : Math.floor(input.evidence.silenceAgeMs / 1000)}`; + const elapsedLine = + input.decision && input.decision.kind === "evaluate" + ? `- elapsedMs: ${input.decision.elapsedMs}` + : `- elapsedMs: ${input.evidence.silenceAgeMs ?? "unknown"}`; + const thresholdLine = + input.decision && input.decision.kind === "evaluate" + ? `- Threshold applied: ${input.decision.reason}` + : null; return [ `Paperclip detected ${input.level} output silence on an active heartbeat run.`, "", @@ -1479,7 +1574,10 @@ export function recoveryService(db: Db, deps: { enqueueWakeup: RecoveryWakeup }) `- Last output at: ${input.run.lastOutputAt?.toISOString() ?? "none recorded"}`, `- Last output sequence: ${input.run.lastOutputSeq ?? 0}`, `- Silent for: ${formatDuration(input.evidence.silenceAgeMs)}`, - `- Thresholds: suspicious after ${formatDuration(ACTIVE_RUN_OUTPUT_SUSPICION_THRESHOLD_MS)}, critical after ${formatDuration(ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS)}`, + wallClockLine, + elapsedLine, + thresholdLine, + `- Thresholds: suspicious after ${formatDuration(ACTIVE_RUN_OUTPUT_SUSPICION_THRESHOLD_MS)}, critical after ${formatDuration(ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS)}, likely zombie/stall after ${formatDuration(ACTIVE_RUN_OUTPUT_LIKELY_ZOMBIE_THRESHOLD_MS)} (min run age ${formatDuration(ACTIVE_RUN_OUTPUT_MIN_AGE_MS)})`, `- Process metadata: pid \`${input.run.processPid ?? "unknown"}\`, process group \`${input.run.processGroupId ?? "unknown"}\`, in-memory handle \`${runningProcesses.has(input.run.id) ? "yes" : "no"}\``, "", "## Last Output Excerpt", @@ -1699,7 +1797,37 @@ export function recoveryService(db: Db, deps: { enqueueWakeup: RecoveryWakeup }) prefix, now: input.now, }); - const level = (evidence.silenceAgeMs ?? 0) >= ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS ? "critical" : "suspicious"; + const decision = decideStaleRunEvaluation({ + silenceAgeMs: evidence.silenceAgeMs, + logBytes: input.run.logBytes ?? null, + hasSpawnPid: input.run.processPid != null, + hasInMemoryHandle: runningProcesses.has(input.run.id), + }); + if (decision.kind === "skip" && !existing) { + await logActivity(db, { + companyId: input.run.companyId, + actorType: "system", + actorId: "system", + agentId: input.run.agentId, + runId: input.run.id, + action: "heartbeat.output_stale_evaluation_skipped", + entityType: "heartbeat_run", + entityId: input.run.id, + details: { + source: "recovery.scan_silent_active_runs", + reason: decision.reason, + elapsedMs: decision.elapsedMs, + wallClockSec: decision.wallClockSec, + logBytes: input.run.logBytes ?? null, + hasSpawnPid: input.run.processPid != null, + hasInMemoryHandle: runningProcesses.has(input.run.id), + }, + }); + return { kind: "skipped" as const }; + } + const level = decision.kind === "evaluate" + ? decision.level + : (evidence.silenceAgeMs ?? 0) >= ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS ? "critical" : "suspicious"; if (existing) { if (level === "critical" && existing.priority !== "high") { await issuesSvc.update(existing.id, { @@ -1710,8 +1838,14 @@ export function recoveryService(db: Db, deps: { enqueueWakeup: RecoveryWakeup }) "", `- Run: \`${input.run.id}\``, `- Silent for: ${formatDuration(evidence.silenceAgeMs)}`, + decision.kind === "evaluate" + ? `- wallClockSec: ${decision.wallClockSec}` + : null, + decision.kind === "evaluate" + ? `- elapsedMs: ${decision.elapsedMs}` + : null, `- Last output at: ${input.run.lastOutputAt?.toISOString() ?? "none recorded"}`, - ].join("\n"), { runId: input.run.id }); + ].filter((line): line is string => line != null).join("\n"), { runId: input.run.id }); await ensureSourceIssueCommentedForStaleEvaluation({ sourceIssue, evaluationIssue: existing, @@ -1738,6 +1872,7 @@ export function recoveryService(db: Db, deps: { enqueueWakeup: RecoveryWakeup }) evidence, level, now: input.now, + decision: decision.kind === "evaluate" ? decision : undefined, }); let evaluation: Awaited>; try { diff --git a/server/src/services/recovery/stale-run-evaluation.test.ts b/server/src/services/recovery/stale-run-evaluation.test.ts new file mode 100644 index 00000000..aa14e5ab --- /dev/null +++ b/server/src/services/recovery/stale-run-evaluation.test.ts @@ -0,0 +1,173 @@ +import { describe, expect, it } from "vitest"; +import { + ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS, + ACTIVE_RUN_OUTPUT_LIKELY_ZOMBIE_THRESHOLD_MS, + ACTIVE_RUN_OUTPUT_MIN_AGE_MS, + ACTIVE_RUN_OUTPUT_NEAR_EMPTY_BYTES, + ACTIVE_RUN_OUTPUT_SUSPICION_THRESHOLD_MS, + decideStaleRunEvaluation, +} from "./service.js"; + +const MIN_AGE_MS = ACTIVE_RUN_OUTPUT_MIN_AGE_MS; +const ZOMBIE_MS = ACTIVE_RUN_OUTPUT_LIKELY_ZOMBIE_THRESHOLD_MS; +const SUSPICION_MS = ACTIVE_RUN_OUTPUT_SUSPICION_THRESHOLD_MS; +const CRITICAL_MS = ACTIVE_RUN_OUTPUT_CRITICAL_THRESHOLD_MS; +const NEAR_EMPTY = ACTIVE_RUN_OUTPUT_NEAR_EMPTY_BYTES; + +describe("decideStaleRunEvaluation (ORA-289)", () => { + it("skips runs without a silence anchor", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: null, + logBytes: 0, + hasSpawnPid: false, + hasInMemoryHandle: false, + }); + expect(decision.kind).toBe("skip"); + if (decision.kind === "skip") { + expect(decision.reason).toBe("no_silence_anchor"); + expect(decision.elapsedMs).toBeNull(); + expect(decision.wallClockSec).toBeNull(); + } + }); + + it("ignores runs younger than 30s even when the log is empty", () => { + const oneSecondOld = decideStaleRunEvaluation({ + silenceAgeMs: 1_000, + logBytes: 0, + hasSpawnPid: false, + hasInMemoryHandle: false, + }); + expect(oneSecondOld.kind).toBe("skip"); + if (oneSecondOld.kind === "skip") { + expect(oneSecondOld.reason).toBe("too_young"); + expect(oneSecondOld.elapsedMs).toBe(1_000); + expect(oneSecondOld.wallClockSec).toBe(1); + } + + const twentyNineSecondOld = decideStaleRunEvaluation({ + silenceAgeMs: MIN_AGE_MS - 1, + logBytes: 0, + hasSpawnPid: false, + hasInMemoryHandle: false, + }); + expect(twentyNineSecondOld.kind).toBe("skip"); + if (twentyNineSecondOld.kind === "skip") { + expect(twentyNineSecondOld.reason).toBe("too_young"); + } + }); + + it("ignores runs younger than 30s even when the log has bootstrap bytes", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: 5_000, + logBytes: 180, + hasSpawnPid: true, + hasInMemoryHandle: true, + }); + expect(decision.kind).toBe("skip"); + if (decision.kind === "skip") { + expect(decision.reason).toBe("too_young"); + } + }); + + it("treats a >5 min run with 0-byte log and no spawn PID as a likely zombie", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: ZOMBIE_MS + 30_000, + logBytes: 0, + hasSpawnPid: false, + hasInMemoryHandle: true, + }); + expect(decision.kind).toBe("evaluate"); + if (decision.kind === "evaluate") { + expect(decision.level).toBe("suspicious"); + expect(decision.reason).toBe("likely_zombie_or_stall"); + expect(decision.wallClockSec).toBe(Math.floor((ZOMBIE_MS + 30_000) / 1000)); + expect(decision.elapsedMs).toBe(ZOMBIE_MS + 30_000); + } + }); + + it("treats a >5 min run with <200-byte log and no in-memory handle as a likely stall", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: 6 * 60_000, + logBytes: 120, + hasSpawnPid: true, + hasInMemoryHandle: false, + }); + expect(decision.kind).toBe("evaluate"); + if (decision.kind === "evaluate") { + expect(decision.level).toBe("suspicious"); + expect(decision.reason).toBe("likely_zombie_or_stall"); + expect(decision.wallClockSec).toBe(360); + expect(decision.elapsedMs).toBe(6 * 60_000); + } + }); + + it("does NOT fire the likely-zombie branch when log bytes are at/above the near-empty boundary", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: 7 * 60_000, + logBytes: NEAR_EMPTY, + hasSpawnPid: false, + hasInMemoryHandle: false, + }); + // Above the near-empty boundary, the heuristic defers to the general + // suspicion threshold; 7 min is below 60 min so we skip with below_threshold. + expect(decision.kind).toBe("skip"); + if (decision.kind === "skip") { + expect(decision.reason).toBe("below_threshold"); + } + }); + + it("does NOT fire the likely-zombie branch when both process anchors are present", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: 7 * 60_000, + logBytes: 0, + hasSpawnPid: true, + hasInMemoryHandle: true, + }); + expect(decision.kind).toBe("skip"); + if (decision.kind === "skip") { + expect(decision.reason).toBe("below_threshold"); + } + }); + + it("still files the general suspicious case after 60 min of silence", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: SUSPICION_MS + 1_000, + logBytes: 4_096, + hasSpawnPid: true, + hasInMemoryHandle: true, + }); + expect(decision.kind).toBe("evaluate"); + if (decision.kind === "evaluate") { + expect(decision.level).toBe("suspicious"); + expect(decision.reason).toBe("above_suspicion_threshold"); + } + }); + + it("escalates to critical once the run crosses 4 h of silence", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: CRITICAL_MS + 1_000, + logBytes: 4_096, + hasSpawnPid: true, + hasInMemoryHandle: true, + }); + expect(decision.kind).toBe("evaluate"); + if (decision.kind === "evaluate") { + expect(decision.level).toBe("critical"); + expect(decision.reason).toBe("above_critical_threshold"); + } + }); + + it("reports wallClockSec / elapsedMs in the evaluate decision so the operator can confirm the threshold", () => { + const decision = decideStaleRunEvaluation({ + silenceAgeMs: 6 * 60_000 + 500, + logBytes: 0, + hasSpawnPid: false, + hasInMemoryHandle: false, + }); + expect(decision.kind).toBe("evaluate"); + if (decision.kind === "evaluate") { + expect(decision.elapsedMs).toBe(6 * 60_000 + 500); + expect(decision.wallClockSec).toBe(360); + } + }); +});