diff --git a/server/src/__tests__/agent-start-lock-liveness.test.ts b/server/src/__tests__/agent-start-lock-liveness.test.ts index 338cd9ed2e82..5f5c53092c4b 100644 --- a/server/src/__tests__/agent-start-lock-liveness.test.ts +++ b/server/src/__tests__/agent-start-lock-liveness.test.ts @@ -3,6 +3,7 @@ import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import { _resetAgentStartLocksForTesting, describeHeldAgentStartLocks, + LOCK_HELD_WARN_MS, withAgentStartLock, } from "../services/agent-start-lock.js"; import { @@ -301,3 +302,74 @@ describe("agent start lock metrics publication (PEN-3305)", () => { expect(afterRelease.size).toBe(0); }); }); + +/** + * BLO-35878. `LOCK_HELD_WARN_MS` was module-private until this change and is + * now exported, so that a *phase* inside the critical section can be judged + * against the same budget the lock itself enforces rather than against a + * second threshold invented beside it. `heartbeat.ts` imports it to decide + * when one `reapOrphanedRuns` sweep has, on its own, consumed the whole + * budget — which is the discriminator the hold gauge cannot provide, because + * it reports a section's total duration with no breakdown. That is how a + * 245–1586 s regression came to be attributed to hindsight recall, a + * subsystem that never runs on this path. + * + * An exported constant is only worth importing if it is still the number the + * lock actually acts on. Nothing else pins that: the suite above stubs `warn` + * globally and every one of its tests advances well past the threshold, so a + * divergence between the exported value and the interval that consumes it + * would leave all of them green while every caller's comparison silently + * shifted. This asserts the coupling at the edge, where it is observable. + */ +describe("exported lock budget is the threshold the lock acts on (BLO-35878)", () => { + let warn!: ReturnType>; + + beforeEach(() => { + warn = vi.spyOn(logger, "warn").mockImplementation(() => logger); + vi.spyOn(logger, "error").mockImplementation(() => logger); + }); + + afterEach(() => { + vi.useRealTimers(); + vi.restoreAllMocks(); + _resetAgentStartLocksForTesting(); + }); + + it("first warns at exactly LOCK_HELD_WARN_MS, reporting that same value as its budget", async () => { + vi.useFakeTimers(); + const agentId = randomUUID(); + const gate = deferred(); + const held = withAgentStartLock(agentId, () => gate.promise, coalesced); + + const warnsForAgent = () => + warn.mock.calls.filter( + ([fields]) => (fields as { agentId?: string } | undefined)?.agentId === agentId, + ); + + // One millisecond short of the exported budget: nothing has overrun yet. + // If the export were larger than the interval that consumes it, the lock + // would already have warned here and this would fail. + await vi.advanceTimersByTimeAsync(LOCK_HELD_WARN_MS - 1); + expect(warnsForAgent()).toHaveLength(0); + + // Crossing it produces exactly one line. If the export were smaller than + // the interval, no line would have landed yet and this would fail. So the + // two assertions bracket the value from both sides rather than asserting + // "some warn eventually happens". + await vi.advanceTimersByTimeAsync(1); + expect(warnsForAgent()).toHaveLength(1); + + // `heldMs` is the lock's own measurement and `warnAfterMs` is the budget + // it judged against. Both must equal the exported constant, or a caller + // comparing its phase duration to that constant is comparing against a + // number the lock does not use. + expect(warnsForAgent()[0]?.[0]).toMatchObject({ + agentId, + heldMs: LOCK_HELD_WARN_MS, + warnAfterMs: LOCK_HELD_WARN_MS, + }); + + gate.resolve("done"); + await held; + }); +}); diff --git a/server/src/services/agent-start-lock.ts b/server/src/services/agent-start-lock.ts index 1799038bd03d..cb5e479054d1 100644 --- a/server/src/services/agent-start-lock.ts +++ b/server/src/services/agent-start-lock.ts @@ -74,8 +74,17 @@ import { logger } from "../middleware/logger.js"; * still happens exactly once. */ -/** Warn (do not bypass) when one critical section runs longer than this. */ -const LOCK_HELD_WARN_MS = 30_000; +/** + * Warn (do not bypass) when one critical section runs longer than this. + * + * Exported (BLO-35878) so the section's own phases can be judged against the + * same budget they consume. The hold gauge says an agent's lock was held for N + * seconds; it cannot say by what, which is why a 1586 s hold was attributed to + * a plugin that never runs on this path. A phase that on its own exceeds the + * lock's warn budget is by definition the hold, so it logs under the same + * threshold rather than a second one invented next to it. + */ +export const LOCK_HELD_WARN_MS = 30_000; /** * Escalate the overrun log from `warn` to `error` past this (PEN-3305). diff --git a/server/src/services/heartbeat.ts b/server/src/services/heartbeat.ts index e1c22c9889c5..e2138a77fcbd 100644 --- a/server/src/services/heartbeat.ts +++ b/server/src/services/heartbeat.ts @@ -504,7 +504,7 @@ import { PROVIDER_CAPACITY_MAX_HORIZON_MS } from "./provider-capacity-horizon-bo import { productivityReviewService } from "./productivity-review.js"; import { resolveRequiredSuccessfulRunHandoffOnValidPath } from "./successful-run-handoff-state.js"; import { taskWatchdogService } from "./task-watchdogs.js"; -import { runDetachedFromAgentStartLock, withAgentStartLock } from "./agent-start-lock.js"; +import { LOCK_HELD_WARN_MS, runDetachedFromAgentStartLock, withAgentStartLock } from "./agent-start-lock.js"; import { evaluateAgentInvokability, evaluateAgentInvokabilityFromDb, @@ -27291,7 +27291,43 @@ export function heartbeatService(db: Db, options: HeartbeatServiceOptions = {}) } const policy = parseHeartbeatPolicy(agent); if (hasExternalLifecycle(agent.adapterType)) { - await reapOrphanedRuns({ suppressDispatchAfterReap: true }); + // BLO-35878: time this. This is the only `reapOrphanedRuns` call site + // inside the agent start lock, and the sweep is NOT agent-scoped: it + // sweeps every `running` run in the instance, issuing per-run k8s reads + // and writes. So every external-lifecycle agent's dispatch pass pays a + // full cluster-wide sweep, and N concurrently-dispatching agents run N + // redundant copies of it against one API server and one DB pool. + // + // Not covered here: the startup reap and the periodic scheduler tick's + // reap (both in `index.ts`) run outside the lock and are not timed. + // `reapOrphanedRuns` has no in-flight latch, so the tick's sweep can run + // concurrently with this one, and a large `reapMs` below can mean this + // sweep was contending with it for the same k8s API and DB pool rather + // than being slow on its own. This line cannot separate those two. + // + // The hold gauge (`paperclip_agent_start_lock_held_seconds`) reports the + // section's total duration with no breakdown, which is why a 245–1586 s + // regression was attributed to hindsight recall — recall runs in the + // out-of-process plugin worker off the `plugin_event_outbox`, and + // nothing on this path awaits it. This line is the discriminator: a reap + // that alone exceeds the lock's warn budget names itself in the log next + // to the hold it caused. + // + // Timed in `finally` so a sweep that stalls and then throws (its first + // `running` select sits outside its per-stage catches, so a slow pool + // acquire that rejects propagates) still logs its duration. + const reapStartedAtMs = Date.now(); + try { + await reapOrphanedRuns({ suppressDispatchAfterReap: true }); + } finally { + const reapMs = Date.now() - reapStartedAtMs; + if (reapMs >= LOCK_HELD_WARN_MS) { + logger.warn( + { agentId, reapMs, warnAfterMs: LOCK_HELD_WARN_MS }, + "orphan reap alone exceeded the agent start lock budget; it is holding dispatch for this agent", + ); + } + } } // BLO-12990 Fix #1 / BLO-20775: stale/silent running runs must not block new // high-priority work. Fetch full run rows so `isRunOccupyingSlot` can partition