Merge ora-289-stale-run-young-threshold: skip young runs and surface wallClockSec

fix(recovery): skip young runs (<30s) and surface wallClockSec on stale-run alerts (ORA-289)
The 0-byte / <200-byte run-log heuristic in stale_active_run_evaluation fires for both genuine stalls (ORA-284 / ORA-275 / ORA-276 class) and brand-new runs that have not yet produced output (class-1 false positives). Most firings were class-1, so operators could not trust the alert. - Add ACTIVE_RUN_OUTPUT_MIN_AGE_MS = 30s: runs younger than this are skipped regardless of log size, eliminating the class-1 noise. - Add ACTIVE_RUN_OUTPUT_LIKELY_ZOMBIE_THRESHOLD_MS = 5min with a near-empty log (<200 bytes) AND no spawn PID / no in-memory process handle, so genuine stalls fire at the operator's SLA instead of waiting for the 60-minute general suspicion threshold. - General 60-min suspicion and 4-h critical thresholds are unchanged. - Extract the rule into a pure decideStaleRunEvaluation() helper and thread the resulting decision into the issue body so wallClockSec and elapsedMs are visible on every new evaluation, with a 'Threshold applied' line explaining which branch fired. - Add unit tests covering: missing silence anchor, too-young, zombie, stall, near-empty boundary, both-process-anchors-present, general suspicion, critical escalation, and wallClockSec/elapsedMs reporting.
2026-06-22 15:22:34 +00:00 · 2026-06-22 01:14:08 +00:00
2 changed files with 311 additions and 3 deletions
@@ -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<ReturnType<typeof collectStaleRunEvidence>>;
    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<ReturnType<typeof issuesSvc.create>>;
    try {
@@ -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);
+    }
+  });
+});