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

Merge pull request #1: fix(opencode-local): pad prompts below the opencode 1.16.2 silent-exit floor (ORA-284)

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<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 {

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);
+    }
+  });
+});