From 6188a90df1738d4abb351685232dd1741c21f2db Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 11:34:17 +0100 Subject: [PATCH 01/20] feat(herdr): wire mode-aware AUDIT_PHASE2_PARALLELISM through the dispatch spawn path (WL-0MT50S9JW001DHME) - DowntimeSpawnConfig gains a genuine freeSlots signal; the Phase 2 parallelism decision is PARALLELISM=2 iff cheap mode AND slotBudget>=2 AND freeSlots>=2 AND a single-flight budget (cap===1). Unbounded (0) and >=2 budgets keep '1' (fixes the prior cap=0 misread); the total slotBudget is no longer used as an availability proxy. - The downtime worker derives spawnConfig from the polled status (free slots, total slots) plus the mode-switch worker's last known mode and threads it through every dispatch path to deps.spawnAgentPane. - createDowntimeDeps forwards it to spawnDowntimePane -> buildDowntimeSpawnOptions; ModeSwitchWorker exposes getLastKnownMode(). - Tests cover the decision table, spawn/config forwarding, tick derivation, unknown-mode fallback, and getLastKnownMode. AC5 (measured outcome) is delegated to operational follow-up WL-0MUFD33FT0080OD5. --- packages/herdr/README.md | 35 +++-- packages/herdr/src/downtime-worker.test.ts | 96 ++++++++++-- packages/herdr/src/downtime-worker.ts | 143 +++++++++++++----- packages/herdr/src/index.test.ts | 23 +++ packages/herdr/src/index.ts | 8 +- packages/herdr/src/mode-switch-worker.test.ts | 34 +++++ packages/herdr/src/mode-switch-worker.ts | 12 ++ src/version.ts | 2 +- 8 files changed, 290 insertions(+), 63 deletions(-) diff --git a/packages/herdr/README.md b/packages/herdr/README.md index 1adf0a543..47aa5bea0 100644 --- a/packages/herdr/README.md +++ b/packages/herdr/README.md @@ -505,17 +505,30 @@ makes the item dispatchable again on the next idle poll. > var (legacy fallback, integer ≥ 1): > > - **`AUDIT_PHASE2_PARALLELISM=1`** (safe default): fast mode, cheap mode -> with full dispatch budget, or config absent. Children run strictly -> sequentially — the skill's documented historical mode. A parent audit -> needs exactly **2 local slots** (parent + at most one child). -> - **`AUDIT_PHASE2_PARALLELISM=2`**: cheap mode AND a second slot is free -> AND the concurrent dispatch budget allows (≤ 1 concurrent dispatch). -> Up to 2 Phase 2 children run in parallel. Since the parent already -> completed Phase 1, the max concurrent streams per audit is 2 — the -> children — which fits cheap mode's 2-slot pool. This is only enabled -> when the combined dispatch budget would not exceed the slot capacity -> (e.g., with concurrent-dispatch cap ≥ 2, PARALLELISM stays at 1 to -> prevent multiple audits × 2 children from exceeding the 2-slot budget). +> without a genuinely free second slot, a non-single-flight dispatch budget, +> or config absent. Children run strictly sequentially — the skill's +> documented historical mode. A parent audit needs exactly **2 local +> slots** (parent + at most one child). +> - **`AUDIT_PHASE2_PARALLELISM=2`**: cheap mode AND a second slot is +> GENUINELY free at dispatch time AND the dispatch is single-flight. Up to +> 2 Phase 2 children run in parallel. Since the parent already completed +> Phase 1, the max concurrent streams per audit is 2 — the children — +> which fits cheap mode's 2-slot pool. +> +> The operative availability signal is the **free-slot count**, never the +> total slot budget: a mode can have a 2-slot pool with only one slot free. +> An unbounded dispatch budget (`concurrentDispatchCap = 0`) or a budget of +> ≥ 2 keeps `PARALLELISM` at `1` — a second audit could otherwise run and +> two audits × 2 children would exceed the cheap pool. Only a single-flight +> budget (`1`, the default pipeline bound) enables `'2'`. +> +> Production wiring (WL-0MT50S9JW001DHME): the downtime worker passes a +> `DowntimeSpawnConfig` — the current proxy mode (from the mode-switch +> worker's last observed mode; unknown until polled, which conservatively +> keeps `'1'`), the genuine free-slot snapshot, the mode's total slot +> budget, and the single-flight pipeline cap — through `spawnAgentPane` to +> `buildDowntimeSpawnOptions`, so dispatched audits no longer fall back to +> the serial default when a second slot is truly free. > > A parent audit therefore needs at most **2 local slots** (the two > parallel children), fitting cheap mode's full capacity (2 × 262144 ctx) diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index ea1a9db9a..2aea98035 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -3902,41 +3902,52 @@ describe('downtime pane spawn (send-to-pi.sh)', () => { expect(optionsWithEmptyConfig.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); }); - it('buildDowntimeSpawnOptions returns PARALLELISM=1 in fast mode', () => { + it('buildDowntimeSpawnOptions returns PARALLELISM=1 in fast mode even with free slots', () => { const options = buildDowntimeSpawnOptions('/repo', { - config: { mode: 'fast', slotBudget: 3, concurrentDispatchCap: 1 }, + config: { mode: 'fast', slotBudget: 3, freeSlots: 3, concurrentDispatchCap: 1 }, }); expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); }); - it('buildDowntimeSpawnOptions returns PARALLELISM=2 for cheap mode with free second slot and dispatch budget allows', () => { - // Cheap mode, 2 slots, only 1 concurrent dispatch allowed → 2 children = 2 streams total + it('buildDowntimeSpawnOptions returns PARALLELISM=2 for cheap mode with a genuinely free second slot (single-flight)', () => { + // Cheap mode, 2 slots, both genuinely free, single dispatch at a time → + // 2 children = 2 streams total, fitting the 2-slot pool. const options = buildDowntimeSpawnOptions('/repo', { - config: { mode: 'cheap', slotBudget: 2, concurrentDispatchCap: 0 }, + config: { mode: 'cheap', slotBudget: 2, freeSlots: 2, concurrentDispatchCap: 1 }, }); expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('2'); }); - it('buildDowntimeSpawnOptions returns PARALLELISM=2 for cheap mode with dispatch cap = 1', () => { - // Single dispatch at a time in cheap mode → 2 children = 2 streams total + it('buildDowntimeSpawnOptions returns PARALLELISM=1 when the second slot is NOT genuinely free', () => { + // The operative signal is freeSlots, never the total slotBudget: a 2-slot + // pool with only 1 free slot cannot run 2 children. const options = buildDowntimeSpawnOptions('/repo', { - config: { mode: 'cheap', slotBudget: 2, concurrentDispatchCap: 1 }, + config: { mode: 'cheap', slotBudget: 2, freeSlots: 1, concurrentDispatchCap: 1 }, }); - expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('2'); + expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); + }); + + it('buildDowntimeSpawnOptions returns PARALLELISM=1 when the dispatch budget is unbounded (cap 0)', () => { + // 0 = unbounded → a second audit could run → 2 audits × 2 children would + // exceed the 2-slot cheap pool. Only cap === 1 is single-flight-safe. + const options = buildDowntimeSpawnOptions('/repo', { + config: { mode: 'cheap', slotBudget: 2, freeSlots: 2, concurrentDispatchCap: 0 }, + }); + expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); }); it('buildDowntimeSpawnOptions returns PARALLELISM=1 when concurrent dispatch budget would exceed slot capacity', () => { // 2+ concurrent dispatches × 2 children each = 4 streams, exceeds 2-slot budget const options = buildDowntimeSpawnOptions('/repo', { - config: { mode: 'cheap', slotBudget: 2, concurrentDispatchCap: 2 }, + config: { mode: 'cheap', slotBudget: 2, freeSlots: 2, concurrentDispatchCap: 2 }, }); expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); }); it('buildDowntimeSpawnOptions returns PARALLELISM=1 when cheap mode slot budget is insufficient', () => { - // Only 1 slot available — cannot run 2 children + // Only 1 slot in the pool — cannot run 2 children const options = buildDowntimeSpawnOptions('/repo', { - config: { mode: 'cheap', slotBudget: 1, concurrentDispatchCap: 1 }, + config: { mode: 'cheap', slotBudget: 1, freeSlots: 1, concurrentDispatchCap: 1 }, }); expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); }); @@ -3944,10 +3955,30 @@ describe('downtime pane spawn (send-to-pi.sh)', () => { it('buildDowntimeSpawnOptions returns PARALLELISM=1 for cheap mode with high dispatch cap', () => { // 3+ concurrent dispatches × 2 children = 6 streams, far exceeds budget const options = buildDowntimeSpawnOptions('/repo', { - config: { mode: 'cheap', slotBudget: 2, concurrentDispatchCap: 3 }, + config: { mode: 'cheap', slotBudget: 2, freeSlots: 2, concurrentDispatchCap: 3 }, }); expect(options.env.AUDIT_PHASE2_PARALLELISM).toBe('1'); }); + + it('spawnDowntimePane forwards the spawn config to the spawn boundary (WL-0MT50S9JW001DHME)', async () => { + const handle = { + unref: vi.fn(), + once: vi.fn((event: string, listener: (arg: unknown) => void) => { + if (event === 'exit') listener(0); + }), + }; + const spawnFn = vi.fn(() => handle) as unknown as DowntimeSpawn; + const config = { + mode: 'cheap' as const, + slotBudget: 2, + freeSlots: 2, + concurrentDispatchCap: 1, + }; + + await spawnDowntimePane('/path/to/send-to-pi.sh', [], { cwd: '/repo', config }, spawnFn); + + expect(spawnFn).toHaveBeenCalledWith('/path/to/send-to-pi.sh', [], { cwd: '/repo', config }); + }); }); // ── Worker orchestrator (AC1/AC5) ───────────────────────────────────── @@ -3959,6 +3990,8 @@ describe('downtime worker orchestrator (createDowntimeWorker)', () => { cooldownMs?: number; status?: unknown; deps?: Partial; + mode?: 'cheap' | 'fast'; + concurrentDispatchCap?: number; } = {}) { const cfg = { enabled: overrides.enabled ?? true, @@ -3967,6 +4000,11 @@ describe('downtime worker orchestrator (createDowntimeWorker)', () => { model: 'plan', cwd: '/repo', noCandidateCooldownMs: overrides.cooldownMs ?? 3_600_000, + // Mode-aware spawn config inputs (WL-0MT50S9JW001DHME). + ...(overrides.mode !== undefined ? { mode: overrides.mode } : {}), + ...(overrides.concurrentDispatchCap !== undefined + ? { concurrentDispatchCap: overrides.concurrentDispatchCap } + : {}), }; const fetcher = vi .fn() @@ -4048,6 +4086,38 @@ describe('downtime worker orchestrator (createDowntimeWorker)', () => { expect(worker.lastDispatchAt).toBe(start + cfg.thresholdMs); }); + it('tick forwards a mode-aware spawnConfig with the genuine free-slot snapshot (WL-0MT50S9JW001DHME)', async () => { + const { worker, deps, cfg } = makeWorker({ mode: 'cheap' }); + const start = 1_000_000; + vi.setSystemTime(start); + await worker.tick(); + + vi.setSystemTime(start + cfg.thresholdMs); + await worker.tick(); + + // idleAllSlotsFree: 4 of 4 slots free, total 4 → forwarded verbatim so + // the spawn boundary never has to reach back into the worker. + expect(deps.spawnAgentPane).toHaveBeenCalledWith( + expect.any(String), + expect.objectContaining({ + spawnConfig: { mode: 'cheap', slotBudget: 4, freeSlots: 4, concurrentDispatchCap: 1 }, + }), + ); + }); + + it('tick omits spawnConfig when the proxy mode is unknown (conservative serial default)', async () => { + const { worker, deps, cfg } = makeWorker(); + const start = 1_000_000; + vi.setSystemTime(start); + await worker.tick(); + + vi.setSystemTime(start + cfg.thresholdMs); + await worker.tick(); + + const call = (deps.spawnAgentPane as ReturnType).mock.calls[0]; + expect(call[1]).not.toHaveProperty('spawnConfig'); + }); + it('requires a fresh full idle period after a dispatch (AC5)', async () => { const { worker, deps, cfg } = makeWorker(); const start = 1_000_000; diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 2357a3b10..807c57d6a 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -1675,6 +1675,14 @@ export interface DowntimeWorkerDeps { itemTitle?: string; itemId?: string; anchorId?: string; + /** + * Mode-aware Phase 2 parallelism inputs (WL-0MT50S9JW001DHME): the + * worker forwards the genuine free-slot snapshot and mode so the spawn + * boundary can set `AUDIT_PHASE2_PARALLELISM` without reaching back + * into the worker. Absent → the spawn falls back to `'1'` (backward + * compatible). + */ + spawnConfig?: DowntimeSpawnConfig; }, ): Promise; /** @@ -2143,7 +2151,7 @@ export function selectCriticalFirstCandidates( async function dispatchFromHerdrList( deps: DowntimeWorkerDeps, items: DowntimeHerdrItem[], - ctx: { cwd: string; model: string; freeSlots?: number; frozen: boolean; panesEligible: boolean; auditEligible: boolean; reviewGate: ReviewQueueGateResult | null; markerStaleWindowMs: number; inFlight: InFlightPanes }, + ctx: { cwd: string; model: string; freeSlots?: number; frozen: boolean; panesEligible: boolean; auditEligible: boolean; reviewGate: ReviewQueueGateResult | null; markerStaleWindowMs: number; inFlight: InFlightPanes; spawnConfig?: DowntimeSpawnConfig }, flags: { auditInFlight: boolean; auditCheckFailed: boolean; auditCheckError?: string; freshnessSkip: boolean; reviewHeld: boolean }, ): Promise { if (items.length === 0) return null; @@ -2206,6 +2214,7 @@ async function dispatchFromHerdrList( cwd: ctx.cwd, selectionPath: 'critical-first', selectionReason: guard.reason, + spawnConfig: ctx.spawnConfig, }); if (outcome.dispatched) return outcome; // A lost CAS race / marker-recovery rollback applies to one candidate: @@ -2310,6 +2319,7 @@ async function dispatchFromHerdrList( cwd: ctx.cwd, selectionPath: 'normal-scan', selectionReason: item.priority === 'critical' ? 'no-live-pane' : 'non-critical', + spawnConfig: ctx.spawnConfig, }); if (outcome.dispatched) return outcome; if (outcome.reason === 'claim-failed') continue; @@ -2378,7 +2388,14 @@ async function dispatchClaimedTier( deps: DowntimeWorkerDeps, kind: DowntimeSkillKind, candidate: DowntimeCandidate, - opts: { model: string; cwd: string; selectionPath?: string; selectionReason?: string }, + opts: { + model: string; + cwd: string; + selectionPath?: string; + selectionReason?: string; + /** Mode-aware Phase 2 parallelism inputs (WL-0MT50S9JW001DHME). */ + spawnConfig?: DowntimeSpawnConfig; + }, ): Promise { const expected = TIER_EXPECTED[kind]; // Dispatcher anchor (C0 WL-0MTR01EU7005SYZG): resolve the dedicated @@ -2504,6 +2521,10 @@ async function dispatchClaimedTier( // leadership. Only set when the anchor resolved (never a bare // undefined key — legacy callers keep their exact opts shape). ...(anchorId !== undefined ? { anchorId } : {}), + // Mode-aware Phase 2 parallelism (WL-0MT50S9JW001DHME): only set when + // the worker supplied a snapshot (legacy/test callers keep the exact + // historical opts shape and fall back to '1'). + ...(opts.spawnConfig !== undefined ? { spawnConfig: opts.spawnConfig } : {}), }, ); if (!spawn.ok) { @@ -2660,7 +2681,7 @@ async function recordDispatchEnrichmentBestEffort( async function dispatchScheduledPrompt( deps: DowntimeWorkerDeps, prompt: ScheduledPrompt, - opts: { model: string; cwd: string }, + opts: { model: string; cwd: string; spawnConfig?: DowntimeSpawnConfig }, ): Promise { const at = new Date().toISOString(); @@ -2721,6 +2742,7 @@ async function dispatchScheduledPrompt( cwd: opts.cwd, paneName: `Downtime ${prompt.id}`, ...(anchorId !== undefined ? { anchorId } : {}), + ...(opts.spawnConfig !== undefined ? { spawnConfig: opts.spawnConfig } : {}), }); if (!spawn.ok) { // Failure trace (WL-0MSLWJ3I70031Z8U AC2 pattern): the audit log @@ -3138,7 +3160,7 @@ export async function computeMostImportantItem( export async function dispatchFromCoordination( deps: DowntimeWorkerDeps, entries: CoordinationEntry[], - opts: { model: string; cwd: string; coordinationDir: string; freeSlots?: number; leaseTtlMs?: number; browseItemCount?: number }, + opts: { model: string; cwd: string; coordinationDir: string; freeSlots?: number; leaseTtlMs?: number; browseItemCount?: number; spawnConfig?: DowntimeSpawnConfig }, now: number = Date.now(), ): Promise { // The leader path REQUIRES the item-fetch dep: without it the leader can @@ -3211,6 +3233,7 @@ export async function dispatchFromCoordination( return await dispatchScheduledPrompt(deps, duePrompt, { model: opts.model, cwd: opts.cwd, + spawnConfig: opts.spawnConfig, }); } } @@ -3314,7 +3337,7 @@ export async function dispatchFromCoordination( deps, kind, toCoordinationCandidate(result.info), - { model: opts.model, cwd: worklogRoot, selectionPath: 'coordination-offer', selectionReason: 'leader-offer' }, + { model: opts.model, cwd: worklogRoot, selectionPath: 'coordination-offer', selectionReason: 'leader-offer', spawnConfig: opts.spawnConfig }, ); if (outcome.dispatched) { // Dispatched — remove the entry so the owner re-queues its next @@ -3577,6 +3600,8 @@ export async function dispatchDowntimeWork( * `DEFAULT_DOWNTIME_MARKER_STALE_WINDOW_MS`. */ markerStaleWindowMs?: number; + /** Mode-aware Phase 2 parallelism inputs (WL-0MT50S9JW001DHME). */ + spawnConfig?: DowntimeSpawnConfig; }, ): Promise { // Per-process PIPELINE single-flight gate (F3, WL-0MT50LKAK001EF5Q): at @@ -3677,7 +3702,7 @@ export async function dispatchDowntimeWork( // spawn. `resolveInFlightPanes` never throws — an unavailable query // degrades to the marker-TTL fallback inside the decision table. const inFlight = await resolveInFlightPanes(deps, opts.cwd); - const ctx = { cwd: opts.cwd, model: opts.model, freeSlots, frozen, panesEligible, auditEligible, reviewGate, markerStaleWindowMs: opts.markerStaleWindowMs ?? DEFAULT_DOWNTIME_MARKER_STALE_WINDOW_MS, inFlight }; + const ctx = { cwd: opts.cwd, model: opts.model, freeSlots, frozen, panesEligible, auditEligible, reviewGate, markerStaleWindowMs: opts.markerStaleWindowMs ?? DEFAULT_DOWNTIME_MARKER_STALE_WINDOW_MS, inFlight, spawnConfig: opts.spawnConfig }; const herdrOutcome = await dispatchFromHerdrList(deps, head.items, ctx, flags); if (herdrOutcome !== null) return herdrOutcome; @@ -4061,22 +4086,35 @@ export type DowntimeSpawn = ( * (WL-0MT50S9JW001DHME). * * When supplied, `buildDowntimeSpawnOptions` selects the Phase 2 parallelism - * level based on the current operating mode and the available dispatch budget: + * level based on the current operating mode, the GENUINELY free slots at + * dispatch time, and the concurrent dispatch budget: * - * - `'1'` (safe default): fast mode, cheap mode with full budget, or config - * not supplied. - * - `'2'`: cheap mode AND a second slot is free AND the concurrent dispatch - * budget allows it (combined streams ≤ slot budget). + * - `'1'` (safe default): fast mode, cheap mode without a genuinely free + * second slot, a non-single-flight dispatch budget, or config not supplied. + * - `'2'`: cheap mode AND a second slot is genuinely free AND exactly one + * dispatch pipeline is in flight (combined streams ≤ slot budget). * - * When the config is absent the function falls back to `'1'` (the historic, - * backward-compatible value). + * `freeSlots` (not `slotBudget`) is the operative input for the second-slot + * check: `slotBudget` is the mode's total pool and being "free" cannot be + * inferred from it. When the config is absent the function falls back to + * `'1'` (the historic, backward-compatible value). */ export interface DowntimeSpawnConfig { /** `'cheap'` or `'fast'` — the proxy's current operating mode. */ mode: 'cheap' | 'fast'; - /** Total number of local proxy slots available (cheap = 2, fast = 3). */ + /** Total number of local proxy slots in the current mode (cheap = 2, fast = 3). */ slotBudget: number; - /** Maximum number of concurrent downtime dispatches allowed (0 = unbounded). */ + /** + * Genuinely free local proxy slots at dispatch time (unowned and not + * processing) — the real availability signal, never the total pool. + */ + freeSlots: number; + /** + * Maximum number of concurrent downtime dispatch pipelines allowed. + * `0` means UNBOUNDED (no cap): other dispatches may be in flight, so the + * cheap 2-slot pool cannot be guaranteed → treated as unsafe for `'2'`. + * Only a single-flight budget (`1`) enables `'2'`. + */ concurrentDispatchCap: number; } @@ -4086,15 +4124,16 @@ export interface DowntimeSpawnConfig { * * `AUDIT_PHASE2_PARALLELISM` is mode-aware (WL-0MT50S9JW001DHME): * - * - `'1'` (safe default): fast mode, cheap mode with full budget, or config - * not supplied. - * - `'2'`: cheap mode AND a second slot is free AND the concurrent dispatch - * budget allows it — up to 2 Phase 2 children run in parallel, fitting the + * - `'1'` (safe default): fast mode, cheap mode without a genuinely free + * second slot, a non-single-flight dispatch budget, or config not supplied. + * - `'2'`: cheap mode AND a second slot is genuinely free AND the dispatch + * is single-flight — up to 2 Phase 2 children run in parallel, fitting the * 2-slot cheap-mode pool (parent already done Phase 1). * * The parent audit always completes Phase 1 before Phase 2 children start, * so the max concurrent streams per audit is 2 (the children). This fits - * cheap mode's slot budget when a second slot is genuinely free. + * cheap mode's slot budget only when a second slot is genuinely free — the + * free count is therefore the operative check, never the total budget. */ export function buildDowntimeSpawnOptions( cwd: string, @@ -4109,23 +4148,22 @@ export function buildDowntimeSpawnOptions( // Default to '1' for backward compatibility when config is absent. let parallelism = '1'; if (opts?.config) { - const { mode, slotBudget, concurrentDispatchCap } = opts.config; - if (mode === 'cheap' && slotBudget >= 2) { - // In cheap mode with ≥ 2 slots, check if a second slot is free. - // PARALLELISM=2 means up to 2 Phase 2 children run in parallel. - // The parent already completed Phase 1, so max concurrent streams = 2. - // Only enable when the dispatch budget allows it: - // - If concurrentDispatchCap is 0 (unbounded), only 1 dispatch at a time - // during cheap mode → 2 children per audit = 2 streams total → safe. - // - If concurrentDispatchCap >= 2, multiple audits could run → each with - // PARALLELISM=2 would exceed 2-slot budget → stay at '1'. - const dispatchBudgetAllows = - concurrentDispatchCap === 0 || concurrentDispatchCap === 1; - if (dispatchBudgetAllows) { - parallelism = '2'; - } + const { mode, slotBudget, freeSlots, concurrentDispatchCap } = opts.config; + // Cheap mode is the 2-slot local pool this bound protects; fast mode + // (cloud-routed, wider pool) keeps the serial historic default. + const cheapPool = mode === 'cheap' && slotBudget >= DOWNTIME_AUDIT_MIN_FREE_SLOTS; + // A GENUINELY free second slot right now — Phase 2 needs the parent plus + // a child = 2 concurrent streams (the total budget is not availability). + const secondSlotFree = freeSlots >= DOWNTIME_AUDIT_MIN_FREE_SLOTS; + // Single-flight dispatch only: an unbounded (0) or ≥ 2 concurrent-dispatch + // budget means a second audit could run, so two audits × 2 children would + // exceed the cheap 2-slot pool. Only cap === 1 is safe. + const dispatchIsSingleFlight = concurrentDispatchCap === 1; + if (cheapPool && secondSlotFree && dispatchIsSingleFlight) { + parallelism = '2'; } - // Fast mode, insufficient budget, or config-supplied but constraints not met → '1' + // Fast mode, no free second slot, non-single-flight budget, or config + // supplied but constraints not met → '1'. } return { @@ -4175,7 +4213,7 @@ export const DOWNTIME_SPAWN_PROBE_MS = 500; export async function spawnDowntimePane( scriptPath: string, args: string[], - opts: { cwd: string }, + opts: { cwd: string; config?: DowntimeSpawnConfig }, spawnFn: DowntimeSpawn = defaultDowntimeSpawn, ): Promise { const child = spawnFn(scriptPath, args, opts); @@ -4239,6 +4277,19 @@ export interface DowntimeWorkerConfig { requiredFreeSlots: number; model: string; cwd: string; + /** + * Current proxy operating mode (WL-0MT50S9JW001DHME). `undefined` when + * unknown (mode switching disabled, or the proxy has not been polled + * yet) → the dispatcher conservatively keeps `AUDIT_PHASE2_PARALLELISM` + * at `'1'`. + */ + mode?: 'cheap' | 'fast'; + /** + * Maximum concurrent dispatch pipelines (WL-0MT50S9JW001DHME). Defaults + * to `DISPATCH_PIPELINE_SINGLE_FLIGHT` (1). Only a single-flight budget + * permits `'2'`; an unbounded (`0`) or ≥ 2 budget keeps `'1'`. + */ + concurrentDispatchCap?: number; /** Pause duration after a genuine empty backlog (no-candidate), ms. */ noCandidateCooldownMs: number; /** Sprint-complete threshold (parent WL-0MTHSHN5V008R5L0). Optional for backward compat — defaults to 20. */ @@ -4848,6 +4899,22 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker ? countFreeUnownedSlots(status.slots) : status.available_slots; + // Mode-aware Phase 2 parallelism inputs (WL-0MT50S9JW001DHME): the + // genuine free-slot snapshot (never the total budget), the current + // proxy mode, and the single-flight pipeline budget. `mode` is + // undefined until the mode-switch worker has observed the proxy, so an + // unknown mode leaves `spawnConfig` absent → the spawn defaults to the + // safe serial '1'. + const spawnConfig: DowntimeSpawnConfig | undefined = + cfg.mode === undefined + ? undefined + : { + mode: cfg.mode, + slotBudget: status.total_slots, + freeSlots, + concurrentDispatchCap: cfg.concurrentDispatchCap ?? DISPATCH_PIPELINE_SINGLE_FLIGHT, + }; + // ── Running-pane liveness (owner-lease qualifier only) ── // Count dispatched downtime panes that are STILL ALIVE (machine-wide, // across roots and leader/instance restarts). @@ -4959,6 +5026,7 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker leaseTtlMs: opts.leaseTtlSeconds ? opts.leaseTtlSeconds * 1000 : DEFAULT_LEASE_TTL_SECONDS * 1000, + spawnConfig, }, ) : await dispatchDowntimeWork(opts.deps, { @@ -4973,6 +5041,7 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker contentionQueueDepth, // Success-marker staleness window (WL-0MU6UL0RJ008IHGT). markerStaleWindowMs: cfg.markerStaleWindowMs, + spawnConfig, }); if (outcome.dispatched) { lastDispatchAt = Date.now(); diff --git a/packages/herdr/src/index.test.ts b/packages/herdr/src/index.test.ts index b630c1805..a284cb05b 100644 --- a/packages/herdr/src/index.test.ts +++ b/packages/herdr/src/index.test.ts @@ -1789,6 +1789,29 @@ describe('createDowntimeDeps', () => { ); }); + it('spawnAgentPane forwards the mode-aware spawnConfig to the spawn boundary (WL-0MT50S9JW001DHME)', async () => { + const spawnFn = vi.fn(() => ({ unref: vi.fn(), once: vi.fn() })); + const deps = createDowntimeDeps('/path/to/send-to-pi.sh', 'Map', spawnFn); + const spawnConfig = { + mode: 'cheap' as const, + slotBudget: 2, + freeSlots: 2, + concurrentDispatchCap: 1, + }; + + await deps.spawnAgentPane('Run /skill:audit WL-AUD — Audit me.', { + model: 'plan', + cwd: '/repo', + spawnConfig, + }); + + expect(spawnFn).toHaveBeenCalledWith( + '/path/to/send-to-pi.sh', + expect.arrayContaining(['--pane-name', 'Downtime audit']), + { cwd: '/repo', config: spawnConfig }, + ); + }); + it('spawnAgentPane honours an explicit paneName (scheduled prompts run as Downtime )', async () => { const spawnFn = vi.fn(() => ({ unref: vi.fn(), once: vi.fn() })); const deps = createDowntimeDeps('/path/to/send-to-pi.sh', 'Map', spawnFn); diff --git a/packages/herdr/src/index.ts b/packages/herdr/src/index.ts index 635aba3e8..62f13db0c 100644 --- a/packages/herdr/src/index.ts +++ b/packages/herdr/src/index.ts @@ -88,6 +88,7 @@ import { type DowntimeClaimResult, type DowntimeSpawn, type DowntimeSpawnResult, + type DowntimeSpawnConfig, type ScheduledPrompt, type DowntimeItemResult, parseShowItemOutput, @@ -1215,13 +1216,14 @@ export function createDowntimeDeps( itemTitle?: string; itemId?: string; anchorId?: string; + spawnConfig?: DowntimeSpawnConfig; }, ): Promise { const kind = skillKindFromPrompt(prompt); return spawnDowntimePane( scriptPath, buildDowntimePaneArgs(kind, prompt, opts), - { cwd: opts.cwd }, + { cwd: opts.cwd, config: opts.spawnConfig }, spawnFn, ); }, @@ -1520,6 +1522,10 @@ async function main(): Promise { // the concurrency limiter. model: s.downtimeModel, cwd: targetCwd, + // Mode-aware Phase 2 parallelism (WL-0MT50S9JW001DHME): the last + // proxy mode observed by the mode-switch worker (`null` until polled + // → `undefined` → the dispatcher conservatively keeps PARALLELISM=1). + mode: modeSwitchWorker.getLastKnownMode() ?? undefined, noCandidateCooldownMs: s.downtimeNoCandidateCooldownMs, // Dispatched success-marker staleness window (WL-0MU6UL0RJ008IHGT). markerStaleWindowMs: s.downtimeMarkerStaleWindowMs, diff --git a/packages/herdr/src/mode-switch-worker.test.ts b/packages/herdr/src/mode-switch-worker.test.ts index 709a4cb51..d05deccb3 100644 --- a/packages/herdr/src/mode-switch-worker.test.ts +++ b/packages/herdr/src/mode-switch-worker.test.ts @@ -301,6 +301,40 @@ describe('fast switch on command', () => { }); }); +// ── Last-known-mode exposure (WL-0MT50S9JW001DHME) ─────────────────── + +describe('getLastKnownMode', () => { + it('returns null before any poll or switch', () => { + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ fetcher: api.fetcher, now }); + expect(worker.getLastKnownMode()).toBeNull(); + }); + + it('returns fast after an operator command triggers the fast switch', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ fetcher: api.fetcher, now }); + worker.onOperatorCommand('http://proxy'); + await flushAsync(); + expect(worker.getLastKnownMode()).toBe('fast'); + }); + + it('returns cheap after an idle tick switches to cheap', async () => { + clock = 1_000_000; + const api = mockAdminApi(); // GET /admin/mode defaults to 'fast' + const worker = createModeSwitchWorker({ fetcher: api.fetcher, now }); + advance(900_000); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(worker.getLastKnownMode()).toBe('cheap'); + }); +}); + // ── Cheap switch trigger ───────────────────────────────────────────── describe('cheap switch trigger', () => { diff --git a/packages/herdr/src/mode-switch-worker.ts b/packages/herdr/src/mode-switch-worker.ts index a8f97a9ad..2bf8ea6b2 100644 --- a/packages/herdr/src/mode-switch-worker.ts +++ b/packages/herdr/src/mode-switch-worker.ts @@ -298,6 +298,14 @@ export interface ModeSwitchWorker { * fail-closed (no switch) and never throw. */ tick(opts: ModeSwitchTickOptions): Promise; + /** + * The most recently observed proxy mode, or `null` when it has not been + * resolved yet (mode switching disabled, or no poll/switch has run). + * Consumed by the downtime dispatcher's mode-aware + * `AUDIT_PHASE2_PARALLELISM` decision (WL-0MT50S9JW001DHME): an unknown + * mode (`null`) conservatively maps to the serial `'1'` default. + */ + getLastKnownMode(): ProxyMode | null; } /** @@ -354,6 +362,10 @@ export function createModeSwitchWorker(deps?: { void fireSwitch(proxyUrl, 'fast'); }, + getLastKnownMode(): ProxyMode | null { + return lastKnownMode; + }, + async tick(opts: ModeSwitchTickOptions): Promise { if (!opts.enabled) return; if (switchInFlight) return; // single-flight: a switch is settling diff --git a/src/version.ts b/src/version.ts index 81c6ebda5..69e375cc7 100644 --- a/src/version.ts +++ b/src/version.ts @@ -1,2 +1,2 @@ // Auto-generated; do not edit. -export const WORKLOG_VERSION = '1.0.14'; +export const WORKLOG_VERSION = '1.0.15'; From 88a144512b1914ea210ed6907ac25c05bf5a72d5 Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 12:34:21 +0100 Subject: [PATCH 02/20] WL-0MU6MXCZZ007ZXT9: gate cheap mode switch on downtime leader and share pane activity --- docs/design/mode-switch-worker.md | 26 +- packages/herdr/README.md | 16 +- packages/herdr/src/index.ts | 29 +- .../herdr/src/mode-switch-integration.test.ts | 2 +- packages/herdr/src/mode-switch-worker.test.ts | 284 +++++++++++++++++- packages/herdr/src/mode-switch-worker.ts | 181 +++++++++-- packages/herdr/src/settings.test.ts | 8 +- packages/herdr/src/settings.ts | 2 +- 8 files changed, 514 insertions(+), 34 deletions(-) diff --git a/docs/design/mode-switch-worker.md b/docs/design/mode-switch-worker.md index 52005e05b..b35874c45 100644 --- a/docs/design/mode-switch-worker.md +++ b/docs/design/mode-switch-worker.md @@ -49,12 +49,33 @@ On plugin/pane restart the idle clock resets to "active now" (construction time), so the proxy stays fast until a fresh full idle window passes (fail-safe). +### Leader-only cheap switching + shared activity (WL-0MU6MXCZZ007ZXT9) + +The mode-switch worker reuses the machine-wide downtime leader +(`DowntimeWorker.isLeader`) — there is no separate election: + +- Only the leader runs the `tick()` cheap-switch logic. Non-leaders skip the + tick entirely, so an idle pane can no longer flip the shared proxy to cheap + while another pane is active (the flip-flop this fixed). +- Every instance (leader and non-leader alike) broadcasts its latest + operator-command timestamp to `mode-activity.json` in the coordination + directory (`getMachineCoordinationDir()`, the same dir as the leader lease). +- The leader's idle evaluation uses `max(localClock, sharedTimestamp)`, so the + proxy stays fast while *any* pane has recent activity. +- The fast switch still fires on the pane that received the command + (fail-open, idempotent) — the active pane may not be the leader. +- The leader probe is read live each tick, so a leadership handover is honoured + on the next tick: the new leader reads the shared activity and continues + from the correct state (no spurious switch during the election). +- **Fail-closed:** if the shared file cannot be read or written, the worker + falls back to its local clock (never a premature cheap switch). + ## 3. Settings (re-read every tick — apply without plugin restart) | Setting | Default | Clamp | |---|---|---| | `modeSwitchEnabled` | `true` | — (disabled ⇒ no scheduler task, no-op hook) | -| `modeSwitchIdleThresholdMs` | `1800000` (30 min) | floor `60000` | +| `modeSwitchIdleThresholdMs` | `3600000` (60 min) | floor `60000` | | `modeSwitchPollIntervalMs` | `10000` | `[5000, 60000]` | The proxy URL is **not** a new setting — it reuses `downtimeProxyUrl`. @@ -71,7 +92,8 @@ time-based plan. ## 5. Key files - `packages/herdr/src/mode-switch-worker.ts` — worker core (idle clock, - admin API client, tick logic, clamps) + leader-gated tick, shared `mode-activity.json` read/write, admin API + client, clamps) - `packages/herdr/src/mode-switch-worker.test.ts` — worker core tests - `packages/herdr/src/mode-switch-integration.test.ts` — wiring tests (settings → worker, route classification, scheduler interval constants) diff --git a/packages/herdr/README.md b/packages/herdr/README.md index 47aa5bea0..062ba4786 100644 --- a/packages/herdr/README.md +++ b/packages/herdr/README.md @@ -688,6 +688,20 @@ proxy idle state: is treated as busy (fail-closed) so the proxy is never switched cheap while real work might be in flight. The single-flight task means a hung tick can never wedge the task; the proxy URL reuses `downtimeProxyUrl`. +- **Leader-only cheap switching + shared activity (WL-0MU6MXCZZ007ZXT9)** — + only the machine-wide downtime leader (`DowntimeWorker.isLeader`, the + existing election — no separate election) runs the idle cheap-switch logic; + non-leader panes skip it entirely. Every pane broadcasts its latest + operator-command timestamp to `mode-activity.json` in the machine + coordination directory (`getMachineCoordinationDir()` — the same directory + as the downtime leader lease), and the leader evaluates idleness against the + **max** of its local clock and that shared timestamp. The proxy therefore + stays fast while *any* pane has recent activity, and idle panes can no + longer flip the shared proxy to cheap behind an active pane's back (the + flip-flop this fixed). Fast switching still fires on whichever pane received + the command (fail-open, idempotent); only the cheap idle switch is + leader-gated. If the shared file cannot be read or written the worker falls + back to its local clock (fail-closed). - **Restart resets to active now** — on plugin/pane restart the idle clock starts from the worker's construction time, so a fresh pane begins with a full idle window before any cheap switch is eligible. @@ -705,7 +719,7 @@ New settings (all optional): when `false` the scheduler registers no mode-switch task and the agent-route hook is a no-op) - `modeSwitchIdleThresholdMs` — Operator-inactivity window before a cheap - switch is considered (default: `1800000` = 30 minutes, hard floor `60000`) + switch is considered (default: `3600000` = 60 minutes, hard floor `60000`) - `modeSwitchPollIntervalMs` — Poll interval for the proxy idle check when evaluating the idle window (default: `10000`, clamped to `[5000, 60000]`) diff --git a/packages/herdr/src/index.ts b/packages/herdr/src/index.ts index 62f13db0c..7ae004a1b 100644 --- a/packages/herdr/src/index.ts +++ b/packages/herdr/src/index.ts @@ -1473,20 +1473,30 @@ async function main(): Promise { // open in the resolved worklog root (--cwd). const targetCwd = wlRoot ?? resolvedCwd ?? process.cwd(); + // Machine-wide coordination directory shared by the downtime leader + // election and the mode-switch shared activity file (WL-0MU6MXCZZ007ZXT9, + // AC2). HERDR_COORDINATION_DIR override wins; default ~/.herdr/downtime/. + const coordinationDir = getMachineCoordinationDir() ?? join(targetCwd, '.worklog'); + // Mode-switch worker: automatically switches the llama-proxy between fast // (cloud) and cheap (local) modes based on operator activity and proxy // idle state. Created with settings.downtimeProxyUrl (reuse, no new URL - // key). Passes `enabled` via the settings flag (modeSwitchEnabled). - // Created BEFORE the downtime worker so we can wire the idle callback. - const modeSwitchWorker: ModeSwitchWorker = createModeSwitchWorker(); + // key). Created AFTER the downtime worker because it needs + // `downtimeWorker.isLeader` for leader-only cheap switching (AC1) and the + // coordination directory for shared activity broadcast (AC2). The idle + // callback is wired through a holder because createDowntimeWorker needs + // `onProxyIdle` before the mode-switch worker exists. + const modeSwitchHolder: { worker?: ModeSwitchWorker } = {}; // Callback: when the downtime dispatcher finds the proxy idle, trigger a // mode-switch tick immediately with the fresh status — avoids the 10 s // poll delay of the independent scheduler task. const onProxyIdle = async (proxyStatus: LlamaStatus): Promise => { + const worker = modeSwitchHolder.worker; + if (!worker) return; // dispatcher cannot tick before the worker exists try { const s = loadSettings(); - await modeSwitchWorker.tick({ + await worker.tick({ enabled: s.modeSwitchEnabled ?? true, idleThresholdMs: s.modeSwitchIdleThresholdMs ?? DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS, proxyUrl: s.downtimeProxyUrl, @@ -1509,7 +1519,7 @@ async function main(): Promise { // ~/.herdr/downtime/. The per-worklog join(targetCwd, '.worklog') // coupling is retired (F6). The instance id is auto-generated at // worker construction (stable for the process lifetime). - coordinationDir: getMachineCoordinationDir() ?? join(targetCwd, '.worklog'), + coordinationDir, config: () => { const s = loadSettings(); return { @@ -1535,6 +1545,15 @@ async function main(): Promise { onProxyIdle, }); + // Mode-switch worker (created AFTER the downtime worker so it can reuse the + // leader probe): only the downtime leader runs the idle cheap switch (AC1) + // and the shared activity file is read from the same coordination dir. + const modeSwitchWorker: ModeSwitchWorker = createModeSwitchWorker({ + isLeader: () => downtimeWorker.isLeader, + coordinationDir, + }); + modeSwitchHolder.worker = modeSwitchWorker; + const selectedItem = await runWorklistTui( fetcher, undefined, diff --git a/packages/herdr/src/mode-switch-integration.test.ts b/packages/herdr/src/mode-switch-integration.test.ts index f568589ac..c40665912 100644 --- a/packages/herdr/src/mode-switch-integration.test.ts +++ b/packages/herdr/src/mode-switch-integration.test.ts @@ -116,7 +116,7 @@ describe('scheduler task configuration', () => { it('idle threshold floor is at least 60s', () => { expect(MODE_SWITCH_IDLE_THRESHOLD_FLOOR_MS).toBeGreaterThanOrEqual(60_000); - expect(DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS).toBe(1_800_000); // 30 minutes + expect(DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS).toBe(3_600_000); // 60 minutes }); it('run timeout watchdog exceeds the admin API timeout (hung ticks get abandoned)', () => { diff --git a/packages/herdr/src/mode-switch-worker.test.ts b/packages/herdr/src/mode-switch-worker.test.ts index d05deccb3..ef6a9c0e3 100644 --- a/packages/herdr/src/mode-switch-worker.test.ts +++ b/packages/herdr/src/mode-switch-worker.test.ts @@ -6,18 +6,24 @@ * Run: npx vitest run packages/herdr/src/mode-switch-worker.test.ts */ -import { describe, it, expect } from 'vitest'; +import { describe, it, expect, beforeEach, afterEach } from 'vitest'; +import { existsSync, mkdtempSync, rmSync, writeFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; import { createModeSwitchWorker, getAdminMode, setAdminMode, fetchProxyStatus, + readSharedActivity, + writeSharedActivity, clampModeSwitchIdleThresholdMs, clampModeSwitchPollIntervalMs, DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS, MODE_SWITCH_IDLE_THRESHOLD_FLOOR_MS, MODE_SWITCH_POLL_INTERVAL_FLOOR_MS, MODE_SWITCH_POLL_INTERVAL_CAP_MS, + MODE_ACTIVITY_FILE, ADMIN_MODE_PATH, ADMIN_SET_MODE_PATH, PROXY_STATUS_PATH, @@ -946,4 +952,280 @@ describe('per-slot operator gate', () => { // Malformed per-slot identity → proxy treated as busy → NO cheap switch. expect(setModePostsMade).toHaveLength(0); }); +}); + +// ── Leader-gated cheap switching + shared activity ──────────────────── +// (WL-0MU6MXCZZ007ZXT9: mode-switch flip-flop — leader election for proxy +// mode changes.) + +describe('leader-gated cheap switching (AC1)', () => { + it('a non-leader skips the entire cheap-switch tick even when idle and proxy idle', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => false, + }); + advance(900_000); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + // No cheap POST, and the tick was skipped before any proxy/mode read. + expect(setModePosts(api)).toHaveLength(0); + expect(api.calls.filter((c) => c.url.endsWith(ADMIN_MODE_PATH))).toHaveLength(0); + expect(worker.getLastKnownMode()).toBeNull(); + }); + + it('the leader performs the cheap switch when idle and proxy idle', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => true, + }); + advance(900_000); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(1); + expect(setModePosts(api)[0].body).toBe(JSON.stringify({ mode: 'cheap' })); + }); + + it('a non-leader still fires the fast switch on an operator command (the active pane may not be the leader, AC4)', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => false, + }); + worker.onOperatorCommand('http://proxy'); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(1); + expect(setModePosts(api)[0].body).toBe(JSON.stringify({ mode: 'fast' })); + }); + + it('defaults to leader when no probe is supplied (legacy/no-coordination single instance)', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ fetcher: api.fetcher, now }); + advance(900_000); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(1); + }); +}); + +describe('shared activity broadcast (AC2/AC4/AC6)', () => { + let dir: string; + + beforeEach(() => { + dir = mkdtempSync(join(tmpdir(), 'wl-mode-activity-')); + }); + + afterEach(() => { + rmSync(dir, { recursive: true, force: true }); + }); + + it('an operator command broadcasts mode-activity.json into the coordination dir', async () => { + clock = 5_000_000; + const api = mockAdminApi(); + const worker = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => false, + coordinationDir: dir, + }); + worker.onOperatorCommand('http://proxy'); + await flushAsync(); + expect(existsSync(join(dir, MODE_ACTIVITY_FILE))).toBe(true); + expect(readSharedActivity(dir)).toBe(5_000_000); + }); + + it('the idle leader reads the active pane\'s shared activity and does NOT cheap-switch (no flip-flop, AC2/AC4)', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + // Two panes on one machine, one coordination dir. The idle pane is the + // downtime leader; the active pane is a non-leader. + const idleLeader = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => true, + coordinationDir: dir, + }); + const activeNonLeader = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => false, + coordinationDir: dir, + }); + // Almost a full idle window passes; the active pane then receives a + // command and broadcasts its activity (local clock alone would switch). + advance(899_000); + activeNonLeader.onOperatorCommand('http://proxy'); + await flushAsync(); + api.reset(); + await idleLeader.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + // Shared activity from the other pane keeps the leader in fast mode. + expect(setModePosts(api)).toHaveLength(0); + }); + + it('the leader cheap-switches once the shared activity ages past the threshold', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + writeSharedActivity(dir, clock); // activity recorded "now" + const leader = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => true, + coordinationDir: dir, + }); + advance(900_000); + await leader.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(1); + expect(setModePosts(api)[0].body).toBe(JSON.stringify({ mode: 'cheap' })); + }); + + it('falls back to the local clock when the shared file is unreadable (AC6, fail-closed)', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + writeFileSync(join(dir, MODE_ACTIVITY_FILE), '{ not valid json', 'utf8'); + const worker = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => true, + coordinationDir: dir, + }); + expect(readSharedActivity(dir)).toBeNull(); + advance(900_000); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + // Local clock is authoritative when the shared state is unreadable. + expect(setModePosts(api)).toHaveLength(1); + expect(setModePosts(api)[0].body).toBe(JSON.stringify({ mode: 'cheap' })); + }); + + it('writeSharedActivity is monotonic — a stale timestamp never regresses a newer one', () => { + expect(writeSharedActivity(dir, 5_000)).toBe(true); + expect(writeSharedActivity(dir, 3_000)).toBe(true); + expect(readSharedActivity(dir)).toBe(5_000); + }); + + it('readSharedActivity/writeSharedActivity are no-ops when no coordination dir is supplied', () => { + expect(writeSharedActivity(undefined, 1)).toBe(false); + expect(readSharedActivity(undefined)).toBeNull(); + }); + + it('writeSharedActivity returns false when the coordination path is unwritable (AC6)', () => { + // A regular file used as a directory: mkdir/write cannot succeed. + const filePath = join(dir, 'not-a-dir'); + writeFileSync(filePath, 'x', 'utf8'); + expect(writeSharedActivity(join(filePath, 'sub'), 1)).toBe(false); + expect(readSharedActivity(join(filePath, 'sub'))).toBeNull(); + }); +}); + +describe('graceful leader transitions (AC5)', () => { + let dir: string; + + beforeEach(() => { + dir = mkdtempSync(join(tmpdir(), 'wl-mode-activity-')); + }); + + afterEach(() => { + rmSync(dir, { recursive: true, force: true }); + }); + + it('a new leader reads shared activity and continues from the correct state (no spurious switch during election)', async () => { + clock = 1_000_000; + const api = mockAdminApi(); + let leader = false; + const worker = createModeSwitchWorker({ + fetcher: api.fetcher, + now, + isLeader: () => leader, + coordinationDir: dir, + }); + advance(900_000); + + // Before the handover the instance is a non-leader: it never switches. + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(0); + + // Another pane was active 10s ago — recorded in the shared file. + writeSharedActivity(dir, clock - 10_000); + + // Leadership handover. The new leader must honour the shared recent + // activity and NOT spuriously switch to cheap during the election. + leader = true; + api.reset(); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(0); + + // Once the shared activity ages past the threshold the new leader + // resumes normal cheap switching. + advance(900_000); + await worker.tick({ + enabled: true, + idleThresholdMs: 900_000, + proxyUrl: 'http://proxy', + proxyStatus: idleStatus(), + }); + await flushAsync(); + expect(setModePosts(api)).toHaveLength(1); + }); +}); + +describe('60-minute default (AC3)', () => { + it('defaults the idle threshold to 3_600_000 ms and clamps invalid input to it', () => { + expect(DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS).toBe(3_600_000); + expect(clampModeSwitchIdleThresholdMs(NaN)).toBe(3_600_000); + expect(clampModeSwitchIdleThresholdMs(-1)).toBe(3_600_000); + // The 60s floor is unchanged. + expect(clampModeSwitchIdleThresholdMs(1_000)).toBe(MODE_SWITCH_IDLE_THRESHOLD_FLOOR_MS); + }); }); \ No newline at end of file diff --git a/packages/herdr/src/mode-switch-worker.ts b/packages/herdr/src/mode-switch-worker.ts index 2bf8ea6b2..6b3fc3e25 100644 --- a/packages/herdr/src/mode-switch-worker.ts +++ b/packages/herdr/src/mode-switch-worker.ts @@ -9,12 +9,28 @@ * the plugin (WL-0MSN3FWV5008KQE9), the worker records the operator * timestamp and fire-and-forget POSTs `/admin/set-mode {"mode":"fast"}`. * A failed switch never blocks or delays the command dispatch (fail-open: - * the pane opens regardless). + * the pane opens regardless). The fast switch fires on the instance that + * received the command, whichever pane that is — see the leader note below. + * - **Leader-only cheap switching (WL-0MU6MXCZZ007ZXT9, AC1):** only the + * downtime leader (`DowntimeWorker.isLeader`, reused — no separate + * election) runs the idle cheap-switch logic. Non-leader instances skip + * `tick()` entirely, so idle panes can no longer flip the shared proxy to + * cheap behind an active pane's back (the flip-flop fix). The leader probe + * is read live each tick, so a leadership handover is honoured on the next + * tick (AC5). + * - **Shared activity broadcast (AC2):** every instance writes its latest + * operator-command timestamp to `mode-activity.json` in the coordination + * directory (`getMachineCoordinationDir()`, the same dir as the downtime + * leader lease) and the leader reads it each tick. The idle clock is the + * max of the local clock and the shared timestamp, so the proxy stays fast + * while **any** pane has recent activity. A read/write failure falls back + * to the local clock (AC6, fail-closed: never a premature cheap switch). * - **Cheap switch on idle:** on each tick (scheduler task, or the downtime - * dispatcher's `onProxyIdle` callback), when the operator has been idle - * (no agent-route commands) for ≥ `modeSwitchIdleThresholdMs` **AND** the - * proxy reports idle (reusing `evaluateIdle` from downtime-worker.ts), the - * worker POSTs `/admin/set-mode {"mode":"cheap"}`. + * dispatcher's `onProxyIdle` callback — the leader is the only pane that + * runs that dispatcher), when the operator has been idle + * (no agent-route commands on any pane) for ≥ `modeSwitchIdleThresholdMs` + * **AND** the proxy reports idle (reusing `evaluateIdle` from + * downtime-worker.ts), the worker POSTs `/admin/set-mode {"mode":"cheap"}`. * **Per-slot operator gate (parent WL-0MT9F67Y3008S0PR, decision 1.a):** * when the proxy serves per-slot identity (`slots[]` valid per * `parseLlamaStatus`), the idle gate requires only ≥ 1 free slot @@ -59,6 +75,8 @@ * paused). Both call the same fail-closed `tick()`. */ +import { existsSync, mkdirSync, readFileSync, renameSync, writeFileSync } from 'node:fs'; +import { join } from 'node:path'; import { evaluateIdle, parseLlamaStatus, @@ -75,8 +93,8 @@ export const ADMIN_MODE_PATH = '/admin/mode'; /** Proxy mode-switch endpoint path. */ export const ADMIN_SET_MODE_PATH = '/admin/set-mode'; -/** Default idle window before switching to cheap mode: 30 minutes. */ -export const DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS = 1_800_000; +/** Default idle window before switching to cheap mode: 60 minutes. */ +export const DEFAULT_MODE_SWITCH_IDLE_THRESHOLD_MS = 3_600_000; /** * Defensive floor for the idle threshold (60s): a trivially small window @@ -111,7 +129,7 @@ export const MODE_SWITCH_RUN_TIMEOUT_MS = 30_000; /** * Clamp the mode-switch idle threshold: reject negative/non-finite (fall - * back to the 30-minute default) and floor at 60s so the operator cannot + * back to the 60-minute default) and floor at 60s so the operator cannot * configure an immediate cheap-switch. */ export function clampModeSwitchIdleThresholdMs(value: number): number { @@ -133,6 +151,76 @@ export function clampModeSwitchPollIntervalMs(value: number): number { ); } +// ── Shared activity (cross-pane arbitration) ───────────────────────── + +/** + * Name of the shared activity file written into the coordination directory. + * Every mode-switch worker instance (leader and non-leader alike) broadcasts + * its latest operator-command timestamp here so the downtime leader can + * evaluate idleness against activity from *any* pane (AC2). The file is a + * tiny JSON object (`{ "lastActivityAt": }`) written atomically. + */ +export const MODE_ACTIVITY_FILE = 'mode-activity.json'; + +/** Shared activity record shape (tolerant reader). */ +interface ModeActivityRecord { + lastActivityAt: number; +} + +/** + * Read the shared operator-activity timestamp from the coordination + * directory. Returns the epoch-ms timestamp, or null when the coordination + * directory is unset, the file is absent/unreadable/malformed, or the value + * is not a finite number. A null result makes the caller fall back to its + * local clock (fail-closed, AC6) — never a premature cheap switch. + */ +export function readSharedActivity(coordinationDir: string | undefined): number | null { + if (!coordinationDir) return null; + try { + const path = join(coordinationDir, MODE_ACTIVITY_FILE); + if (!existsSync(path)) return null; + const raw: unknown = JSON.parse(readFileSync(path, 'utf8')); + if (typeof raw !== 'object' || raw === null) return null; + const ts = (raw as Partial).lastActivityAt; + return typeof ts === 'number' && Number.isFinite(ts) ? ts : null; + } catch { + return null; // unreadable / invalid JSON → fall back to the local clock + } +} + +/** + * Broadcast an operator-activity timestamp to the shared activity file so + * every pane's mode-switch worker sees it (AC2). The write is atomic (temp + * file + rename) and monotonic (never regresses an existing newer value). + * Returns true on success and false when the coordination directory is unset + * or the write fails — the caller then relies on its local clock (AC6). + */ +export function writeSharedActivity( + coordinationDir: string | undefined, + timestamp: number, +): boolean { + if (!coordinationDir) return false; + try { + mkdirSync(coordinationDir, { recursive: true }); + const path = join(coordinationDir, MODE_ACTIVITY_FILE); + const existing = readSharedActivity(coordinationDir); + const value = existing !== null ? Math.max(existing, timestamp) : timestamp; + const payload = JSON.stringify({ lastActivityAt: value }); + const tmp = `${path}.tmp-${process.pid}-${Date.now()}`; + writeFileSync(tmp, payload, 'utf8'); + try { + renameSync(tmp, path); + } catch { + // rename-over-existing is not portable (Windows); fall back to a + // direct small synchronous write. + writeFileSync(path, payload, 'utf8'); + } + return true; + } catch { + return false; // permission/IO error → local clock only (AC6) + } +} + // ── Types ───────────────────────────────────────────────────────────── /** Proxy operating mode: 'fast' (cloud-backed) or 'cheap' (local-first). */ @@ -308,23 +396,61 @@ export interface ModeSwitchWorker { getLastKnownMode(): ProxyMode | null; } +/** + * Optional dependencies and coordination hooks for the mode-switch worker. + * All fields are injectable for tests; production (index.ts) passes only + * `isLeader` and `coordinationDir`. + */ +export interface ModeSwitchWorkerOptions { + /** Injectable HTTP fetcher (tests). */ + fetcher?: AdminApiFetcher; + /** Injectable time source (tests). */ + now?: Now; + /** + * Leadership probe reused from the downtime worker + * (`DowntimeWorker.isLeader` — constraint: reuse the existing election). + * Read live on every tick so a leadership handover is honoured without + * reconstructing the worker (AC1/AC5). Defaults to `() => true`: with no + * coordination there is exactly one instance and it is always the leader. + */ + isLeader?: () => boolean; + /** + * Machine-wide coordination directory containing the shared activity file + * (AC2). When absent the worker keeps the original process-local idle + * clock (no shared state). + */ + coordinationDir?: string; +} + /** * Create the mode-switch worker. Construction sets * `lastOperatorCommandAt = now()` — the idle clock resets to "active now", * so after a plugin restart the proxy stays fast until a fresh full idle * window passes (fail-safe, operator decision Q3: "a"). * - * @param deps - Injectable fetcher/time (tests). + * @param deps - Injectable fetcher/time plus the leader probe and shared + * activity-coordination directory (tests / index.ts). */ -export function createModeSwitchWorker(deps?: { - fetcher?: AdminApiFetcher; - now?: Now; -}): ModeSwitchWorker { +export function createModeSwitchWorker(deps?: ModeSwitchWorkerOptions): ModeSwitchWorker { const fetcher = deps?.fetcher ?? (globalThis.fetch as unknown as AdminApiFetcher); const now = deps?.now ?? Date.now; + const isLeader = deps?.isLeader ?? (() => true); + const coordinationDir = deps?.coordinationDir; /** Last operator agent-route command timestamp; construction = "now" (restart reset). */ let lastOperatorCommandAt: number = now(); + + /** + * Latest operator-activity timestamp across all panes: the max of this + * process's local clock and the shared activity file. Falls back to the + * local clock when the shared state is unreadable or unwritable (AC6, + * fail-closed: never a premature cheap switch off stale cross-pane state). + */ + const effectiveLastActivityAt = (): number => { + const shared = readSharedActivity(coordinationDir); + if (shared === null) return lastOperatorCommandAt; + return Math.max(lastOperatorCommandAt, shared); + }; /** Last known proxy mode (refreshed via GET /admin/mode on each poll). */ let lastKnownMode: ProxyMode | null = null; /** True while a mode-switch POST is in flight (per-process single-flight). */ @@ -356,9 +482,19 @@ export function createModeSwitchWorker(deps?: { return { onOperatorCommand(proxyUrl: string): void { - // Record operator activity (agent-route command). + // Record operator activity (agent-route command) on the local clock. lastOperatorCommandAt = now(); - // Fire-and-forget fast switch (fail-open: never blocks dispatch). + // Broadcast to every pane — leader and non-leader alike — so the + // downtime leader's idle evaluation sees activity from any pane (AC2). + // A failed broadcast leaves this process's local clock authoritative + // (AC6, fail-closed). + writeSharedActivity(coordinationDir, lastOperatorCommandAt); + // Fire-and-forget fast switch on the instance that received the + // command (fail-open: never blocks dispatch). Fast is always the safe + // direction, and the operator's active pane may not be the downtime + // leader — gating fast on leadership would leave the proxy in cheap + // while the operator is actively working (AC4). Only the *cheap* idle + // switch is leader-gated; see tick() (AC1). void fireSwitch(proxyUrl, 'fast'); }, @@ -368,12 +504,19 @@ export function createModeSwitchWorker(deps?: { async tick(opts: ModeSwitchTickOptions): Promise { if (!opts.enabled) return; + // Leader-only cheap switching (AC1): non-leader instances skip the + // entire idle cheap-switch logic (no proxy status fetch, no mode read, + // no POST). The probe is read live so a leadership handover is picked + // up on the next tick (AC5). + if (!isLeader()) return; if (switchInFlight) return; // single-flight: a switch is settling - // Idle window: has the operator issued no agent-route command for ≥ - // the threshold? (lastOperatorCommandAt can never be null — restart - // resets to "active now", so a fresh full window is always required.) - const elapsed = now() - lastOperatorCommandAt; + // Idle window: has there been no operator agent-route command on ANY + // pane for ≥ the threshold? (local clock max shared activity, AC2; a + // shared read failure falls back to the local clock, AC6. The local + // clock can never be null — restart resets to "active now", so a fresh + // full window is always required.) + const elapsed = now() - effectiveLastActivityAt(); if (elapsed < opts.idleThresholdMs) return; // Fetch proxy status when not provided (the worker fetches its own diff --git a/packages/herdr/src/settings.test.ts b/packages/herdr/src/settings.test.ts index b9dec50fa..4a8511871 100644 --- a/packages/herdr/src/settings.test.ts +++ b/packages/herdr/src/settings.test.ts @@ -165,10 +165,10 @@ describe('modeSwitchEnabled', () => { }); describe('modeSwitchIdleThresholdMs', () => { - it('defaults to 1_800_000 ms (30 minutes)', () => { - expect(defaultSettings.modeSwitchIdleThresholdMs).toBe(1_800_000); + it('defaults to 3_600_000 ms (60 minutes)', () => { + expect(defaultSettings.modeSwitchIdleThresholdMs).toBe(3_600_000); const path = tempSettingsPath(); - expect(loadSettings(path).modeSwitchIdleThresholdMs).toBe(1_800_000); + expect(loadSettings(path).modeSwitchIdleThresholdMs).toBe(3_600_000); }); it('clamps a persisted value below the 60s floor up to the floor', () => { @@ -183,7 +183,7 @@ describe('modeSwitchIdleThresholdMs', () => { it('falls back to the default when the persisted value is not a number', () => { const path = tempSettingsPath(); writeFileSync(path, JSON.stringify({ ...defaultSettings, modeSwitchIdleThresholdMs: 'later' }), 'utf-8'); - expect(loadSettings(path).modeSwitchIdleThresholdMs).toBe(1_800_000); + expect(loadSettings(path).modeSwitchIdleThresholdMs).toBe(3_600_000); }); }); diff --git a/packages/herdr/src/settings.ts b/packages/herdr/src/settings.ts index e1733fe99..4a6d0cefd 100644 --- a/packages/herdr/src/settings.ts +++ b/packages/herdr/src/settings.ts @@ -87,7 +87,7 @@ export interface PluginSettings { */ modeSwitchEnabled: boolean; /** - * Idle window before switching to cheap mode (ms). Default 1_800_000 (30 min). + * Idle window before switching to cheap mode (ms). Default 3_600_000 (60 min). * A new operator agent-route command resets this timer. */ modeSwitchIdleThresholdMs: number; From e6e556045a9376a1d7fd6620f2aa4d9b55330b5c Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 15:53:37 +0100 Subject: [PATCH 03/20] WL-0MU4URK4H006OFCE: extend dispatch log schema and add pane lifecycle monitor --- packages/herdr/src/downtime-log.test.ts | 82 +++++ packages/herdr/src/downtime-log.ts | 109 +++++++ packages/herdr/src/downtime-worker.test.ts | 302 ++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 221 +++++++++++++ packages/herdr/src/index.ts | 49 +++ packages/herdr/src/pane-lifecycle.test.ts | 212 +++++++++++++ packages/herdr/src/pane-lifecycle.ts | 351 +++++++++++++++++++++ 7 files changed, 1326 insertions(+) create mode 100644 packages/herdr/src/pane-lifecycle.test.ts create mode 100644 packages/herdr/src/pane-lifecycle.ts diff --git a/packages/herdr/src/downtime-log.test.ts b/packages/herdr/src/downtime-log.test.ts index b8d67443d..9d8884158 100644 --- a/packages/herdr/src/downtime-log.test.ts +++ b/packages/herdr/src/downtime-log.test.ts @@ -23,6 +23,7 @@ import { join } from 'node:path'; import { appendDowntimeLogEntry, appendCoordinationLogEntry, + appendPaneCloseLogEntry, auditDispatchedItemIds, implementDispatchedItemIds, riskEffortDispatchedItemIds, @@ -699,3 +700,84 @@ describe('post-spawn enrichment preserves marker semantics (WL-0MUBVL251006JAQ0 expect(markerStillExcludes(after.get('WL-ENR')!, 'plan_complete', Date.now(), 24 * 60 * 60 * 1000, 'id-guard')).toBe(true); }); }); + +// ── Pane-close lifecycle entries (WL-0MU308WSF0002JWN) ──────────────── +// +// The rolling log gains a `pane-close` entry type recording WHY a dispatched +// pane was closed (intake complete / plan complete / audit passed / audit +// failed / requires-attention). Pane-close entries must be ignored by every +// dispatched-marker reader so the existing change-guard semantics are +// unchanged (backward compatible). +describe('pane-close lifecycle entries (WL-0MU308WSF0002JWN)', () => { + it('appends a pane-close entry with every AC1 field and round-trips it', async () => { + const cwd = makeTempCwd(); + await appendPaneCloseLogEntry(cwd, { + entryType: 'pane-close', + timestamp: '2026-01-02T00:00:00.000Z', + itemId: 'WL-1', + itemTitle: 'Auto close me', + paneId: 'w1:p1', + kind: 'plan', + outcome: 'closed-as-plan-complete', + reason: 'item advanced to plan_complete', + closed: true, + }); + + const entries = await readDowntimeLogEntries(cwd); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + entryType: 'pane-close', + timestamp: '2026-01-02T00:00:00.000Z', + itemId: 'WL-1', + itemTitle: 'Auto close me', + paneId: 'w1:p1', + kind: 'plan', + outcome: 'closed-as-plan-complete', + closed: true, + }); + }); + + it('never throws when the worklog dir is unwritable (fail-closed, AC7)', async () => { + const cwd = '/nonexistent/path/' + Math.random().toString(36).slice(2); + await expect( + appendPaneCloseLogEntry(cwd, { + entryType: 'pane-close', + timestamp: '2026-01-02T00:00:00.000Z', + itemId: 'WL-1', + itemTitle: 'x', + paneId: 'w1:p1', + kind: 'plan', + outcome: 'requires-attention', + closed: true, + }), + ).resolves.toBeUndefined(); + }); + + it('a pane-close entry never contaminates the dispatched-marker readers', async () => { + const cwd = makeTempCwd(); + // A standing implement discharge marker for WL-IMP + a pane-close entry + // that reuses the SAME itemId/kind — the marker readers must see only the + // standing marker (the pane-close entry carries entryType, not a marker). + await appendDowntimeLogEntry( + cwd, + JSON.stringify({ itemId: 'WL-IMP', kind: 'implement', stage: 'plan_complete', dispatchedAt: '2026-01-01T00:00:00.000Z' }), + ); + await appendPaneCloseLogEntry(cwd, { + entryType: 'pane-close', + timestamp: '2026-01-02T00:00:00.000Z', + itemId: 'WL-IMP', + itemTitle: 'Implement me', + paneId: 'w1:p9', + kind: 'implement', + outcome: 'requires-attention', + closed: false, + }); + + const entries = await readDowntimeLogEntries(cwd); + expect([...implementDispatchedItemIds(entries)]).toEqual(['WL-IMP']); + expect(dispatchedItemMarkers(entries, 'implement').get('WL-IMP')?.stage).toBe('plan_complete'); + // The enrichment-less pane-close entry must NOT be reconstructed as a + // dispatched pane (only dispatch/enrichment entries carry a paneId). + expect(entries.filter((e) => e.entryType === 'pane-close')).toHaveLength(1); + }); +}); diff --git a/packages/herdr/src/downtime-log.ts b/packages/herdr/src/downtime-log.ts index ae7f0b254..de828a0c9 100644 --- a/packages/herdr/src/downtime-log.ts +++ b/packages/herdr/src/downtime-log.ts @@ -76,6 +76,78 @@ export async function appendCoordinationLogEntry( /** Rolling bound: keep at most this many entries in the log file. */ export const DOWNTIME_LOG_MAX_ENTRIES = 100; +// ── Pane-close lifecycle entries (WL-0MU308WSF0002JWN) ───────────────── + +/** + * Outcome for a pane-lifecycle close event, capturing WHY the pane was + * closed (or, for `requires-attention`, why it was flagged). + */ +export type PaneLifecycleOutcome = + | 'closed-as-intake-complete' + | 'closed-as-plan-complete' + | 'audit-passed' + | 'audit-failed' + | 'requires-attention'; + +/** + * The dispatch kind that spawned the pane (plan / intake / audit / + * risk-effort / implement). Re-exports the worker's `DowntimeSkillKind` + * for the pane-lifecycle module so the worker and log share the same set. + */ +export type PaneLifecycleKind = 'plan' | 'intake' | 'audit' | 'risk-effort' | 'implement'; + +/** + * A pane-close lifecycle event recorded in the rolling dispatch log + * (WL-0MU308WSF0002JWN). These entries are keyed by pane id + outcome so + * the lifecycle collector can track which outcomes have already been + * logged and avoid duplicate entries. + * + * This entry type uses `entryType: 'pane-close'` as a discriminator so + * dispatched-marker readers (which filter by `kind === `) ignore + * pane-close entries entirely. + */ +export interface PaneCloseLogEntry { + /** Discriminator — ensures dispatched-marker readers ignore this entry. */ + entryType: 'pane-close'; + /** ISO-8601 UTC timestamp of the pane-close/log event. */ + timestamp: string; + /** Work item id of the dispatched item. */ + itemId: string; + /** Work item title at the time the pane was closed. */ + itemTitle: string; + /** Pane id (unique per pane, e.g. "w2T:p3"). */ + paneId: string; + /** The dispatch kind that spawned this pane. */ + kind: PaneLifecycleKind; + /** Why the pane was closed (or flagged). */ + outcome: PaneLifecycleOutcome; + /** Human-readable reason (required for `requires-attention`). */ + reason?: string; + /** + * Stable machine-readable reason code (part of the monitor's idempotency + * key — see `pane-lifecycle.ts`). `'none'` for clean terminal outcomes. + */ + reasonCode?: string; + /** Whether the pane was actually closed (false for informational log-only). */ + closed: boolean; +} + +/** + * Append one pane-close lifecycle entry to the rolling dispatch log. + * Fail-closed: never throws — the lifecycle logger must never crash the + * worker. + */ +export async function appendPaneCloseLogEntry( + cwd: string, + entry: PaneCloseLogEntry, +): Promise { + try { + await appendRollingJsonl(cwd, DOWNTIME_LOG_FILE, JSON.stringify(entry)); + } catch { + // fail-closed: pane-close logging must never crash the worker + } +} + /** * One parsed line of the downtime dispatch log: either a dispatch event * (itemId/kind/dispatchedAt/title), a spawn-failure trace @@ -111,6 +183,27 @@ export interface DowntimeLogEntry { error?: string; /** send-to-pi.sh exit code (non-zero spawn-failed trace; null = signal). */ exitCode?: number | null; + /** + * Entry-type discriminator (WL-0MU308WSF0002JWN): `'pane-close'` marks a + * pane-lifecycle close event. Absent on dispatch markers, spawn-failure + * traces, and error entries (backward compatible — marker readers ignore + * unknown fields). + */ + entryType?: string; + /** + * Resolved pane id for a dispatch (post-spawn enrichment entry, + * WL-0MUBVL251006JAQ0) or the pane id a pane-close entry refers to. Absent + * when the pane could not be resolved (backward compatible). + */ + paneId?: string | null; + /** Discriminator for a post-spawn enrichment entry. */ + enrichment?: boolean; + /** + * Stable machine-readable reason code for a pane-close entry + * (WL-0MU308WSF0002JWN) — part of the monitor's idempotency key. Absent on + * legacy/other entries. + */ + reasonCode?: string; } /** @@ -146,6 +239,18 @@ export async function readDowntimeLogEntries(cwd: string): Promise { const ids = new Set(); for (const e of entries) { + if (!isDispatchMarkerEntry(e)) continue; // pane-close/lifecycle entries are not markers // Spawn-failed entries are non-excluding (WL-0MT32F908002YFFA AC2). if (e.outcome === 'spawn-failed') continue; if (e.kind === kind && typeof e.itemId === 'string' && e.itemId.length > 0) { @@ -199,6 +305,7 @@ export function recentDispatchedItemIds( const cutoff = now - windowMs; const ids = new Set(); for (const e of entries) { + if (!isDispatchMarkerEntry(e)) continue; // pane-close/lifecycle entries are not markers // Spawn-failed entries are non-excluding (WL-0MT32F908002YFFA AC2): a // failed spawn is NOT an active run — the pane never appeared, so a new // dispatch must not be blocked by it. @@ -277,6 +384,7 @@ export function dispatchedItemMarkers( ): Map { const markers = new Map(); for (const e of entries) { + if (!isDispatchMarkerEntry(e)) continue; // pane-close/lifecycle entries are not markers // Spawn-failed entries are non-excluding (WL-0MT32F908002YFFA AC2). if (e.outcome === 'spawn-failed') continue; if (e.kind !== kind || typeof e.itemId !== 'string' || e.itemId.length === 0) continue; @@ -368,6 +476,7 @@ export function riskEffortDispatchedItemIds(entries: DowntimeLogEntry[]): Set { const stages = new Map(); for (const e of entries) { + if (!isDispatchMarkerEntry(e)) continue; // pane-close/lifecycle entries are not markers // Spawn-failed entries are non-excluding (WL-0MT32F908002YFFA AC2). if (e.outcome === 'spawn-failed') continue; if (e.kind === kind && typeof e.itemId === 'string' && e.itemId.length > 0) { diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index 2aea98035..2a6ad1055 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -84,6 +84,7 @@ import { parseCriticalCandidatesOutput, parseDepListBlockersOutput, parseShownWorkItem, + parseShowItemOutput, selectCriticalCandidate, criticalSkillKind, resolveDependencyFrontier, @@ -109,6 +110,8 @@ import { runningDowntimePaneItemIds, evaluateCriticalFirstGuard, resolveInFlightPanes, + monitorDispatchedPanes, + DOWNTIME_PANE_LIFECYCLE_INTERVAL_MS, DOWNTIME_POLL_INTERVAL_FLOOR_MS, DEFAULT_DOWNTIME_POLL_INTERVAL_MS, DEFAULT_DOWNTIME_IDLE_THRESHOLD_MS, @@ -152,6 +155,7 @@ import { createRoundRobinRegistry } from './downtime-round-robin.js'; import { DOWNTIME_LOG_FILE, appendDowntimeLogEntry, + appendPaneCloseLogEntry, readDowntimeLogEntries, } from './downtime-log.js'; import { @@ -6453,6 +6457,36 @@ describe('parseShownWorkItem', () => { }); }); +describe('parseShowItemOutput audit verdict (WL-0MU308WSF0002JWN)', () => { + it('reads the TOP-LEVEL auditResult verdict and timestamp', () => { + const info = parseShowItemOutput( + JSON.stringify({ + success: true, + workItem: { id: 'WL-AUD', status: 'completed', stage: 'in_review' }, + auditResult: { + workItemId: 'WL-AUD', + readyToClose: false, + auditedAt: '2026-01-02T00:00:00.000Z', + }, + }), + ); + expect(info).toMatchObject({ + id: 'WL-AUD', + status: 'completed', + stage: 'in_review', + auditedAt: '2026-01-02T00:00:00.000Z', + auditResult: false, + }); + }); + + it('leaves the verdict absent when auditResult is null (no audit recorded)', () => { + const info = parseShowItemOutput( + JSON.stringify({ success: true, workItem: { id: 'WL-AUD2', stage: 'in_review' }, auditResult: null }), + ); + expect(info!.auditResult).toBeUndefined(); + }); +}); + // ── Critical-first: tier wiring (F4, decisions Q1/Q2/Q3) ───────────── describe('dispatch critical-first tier', () => { @@ -10106,3 +10140,271 @@ describe('tick(): owner-lease gate must be per-slot (WL-0MU8807BI008C9ME)', () = } }); }); + +// ── Pane-lifecycle monitor (WL-0MU308WSF0002JWN, child WL-0MU4URK4H006OFCE) ── +// +// The monitor inspects every dispatched pane recorded in the rolling log +// (marker + post-spawn enrichment), classifies its lifecycle outcome, logs a +// pane-close entry, and closes the pane — EXCEPT `implement` panes, which are +// never auto-closed (AC6). Every boundary is fail-closed (AC7). +describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { + const roots: string[] = []; + + function makeRoot(): string { + const root = mkdtempSync(join(tmpdir(), 'pane-lifecycle-')); + roots.push(root); + return root; + } + + afterEach(() => { + for (const root of roots.splice(0)) rmSync(root, { recursive: true, force: true }); + }); + + /** Seed a dispatch marker + its post-spawn enrichment (paneId) entry. */ + async function seedDispatch( + root: string, + opts: { itemId: string; kind: string; paneId: string; stage?: string; title?: string }, + ): Promise { + const marker = { + itemId: opts.itemId, + kind: opts.kind, + dispatchedAt: '2026-01-01T00:00:00.000Z', + cwd: root, + title: opts.title ?? opts.itemId, + stage: opts.stage ?? 'idea', + }; + await appendDowntimeLogEntry(root, JSON.stringify(marker)); + await appendDowntimeLogEntry(root, JSON.stringify({ ...marker, paneId: opts.paneId, enrichment: true })); + } + + /** Deps with a real (rolling-log-appending) recordPaneClose so idempotency works. */ + function monitorDeps(overrides: Partial = {}): DowntimeWorkerDeps { + return makeDeps({ + recordPaneClose: vi.fn(async (entry, cwd) => { + await appendPaneCloseLogEntry(cwd, entry); + }), + ...overrides, + }); + } + + async function paneCloseEntries(root: string) { + return (await readDowntimeLogEntries(root)).filter((e) => e.entryType === 'pane-close'); + } + + it('closes an intake pane and logs closed-as-intake-complete when the item reaches intake_complete', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-1', kind: 'intake', paneId: 'w1:p1', stage: 'idea', title: 'Intake me' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-1', title: 'Intake me', stage: 'intake_complete' }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ ok: true, count: 1, records: [{ paneId: 'w1:p1' }] }), + closePane, + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ checked: 1, logged: 1, closed: 1, errors: 0 }); + expect(closePane).toHaveBeenCalledWith('w1:p1', root); + const pc = await paneCloseEntries(root); + expect(pc).toHaveLength(1); + expect(pc[0]).toMatchObject({ + entryType: 'pane-close', + itemId: 'WL-1', + itemTitle: 'Intake me', + paneId: 'w1:p1', + kind: 'intake', + outcome: 'closed-as-intake-complete', + closed: true, + }); + }); + + it('closes a plan pane and logs closed-as-plan-complete when the item reaches plan_complete', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-2', kind: 'plan', paneId: 'w1:p2', stage: 'intake_complete' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-2', stage: 'plan_complete' }), + closePane, + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ logged: 1, closed: 1 }); + expect(closePane).toHaveBeenCalledWith('w1:p2', root); + expect((await paneCloseEntries(root))[0]).toMatchObject({ outcome: 'closed-as-plan-complete', closed: true }); + }); + + it('closes an audit pane and records the pass/fail verdict (AC5)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-3', kind: 'audit', paneId: 'w1:p3', stage: 'in_review' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ + id: 'WL-3', stage: 'in_review', auditedAt: '2026-01-02T00:00:00.000Z', auditResult: false, + }), + closePane, + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ logged: 1, closed: 1 }); + expect(closePane).toHaveBeenCalledWith('w1:p3', root); + expect((await paneCloseEntries(root))[0]).toMatchObject({ outcome: 'audit-failed', closed: true }); + }); + + it('NEVER closes an implement pane but still logs its in_review completion (AC4/AC6)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-4', kind: 'implement', paneId: 'w1:p4', stage: 'plan_complete' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-4', stage: 'in_review' }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ ok: true, count: 1, records: [{ paneId: 'w1:p4' }] }), + closePane, + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ logged: 1, closed: 0 }); + expect(closePane).not.toHaveBeenCalled(); + expect((await paneCloseEntries(root))[0]).toMatchObject({ + outcome: 'requires-attention', + reasonCode: 'reached-in-review', + closed: false, + }); + }); + + it('is idempotent: a second pass with no state change writes no duplicate entry', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-5', kind: 'plan', paneId: 'w1:p5', stage: 'intake_complete' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-5', stage: 'plan_complete' }), + closePane, + }); + + const first = await monitorDispatchedPanes(deps, root); + const second = await monitorDispatchedPanes(deps, root); + + expect(first).toMatchObject({ logged: 1, closed: 1 }); + expect(second).toMatchObject({ logged: 0, closed: 0 }); + expect(closePane).toHaveBeenCalledTimes(1); + expect(await paneCloseEntries(root)).toHaveLength(1); + }); + + it('logs a NEW entry when the item changes state again (agent-ended → plan_complete)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-6', kind: 'plan', paneId: 'w1:p6', stage: 'intake_complete' }); + const noLivePanes = vi.fn().mockResolvedValue({ ok: true, count: 0, paneIds: [], records: [] }); + // First pass: the agent session has ended but the item is NOT terminal. + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-6', stage: 'intake_complete' }), + getRunningDowntimePanes: noLivePanes, + closePane: vi.fn().mockResolvedValue(true), + }); + await monitorDispatchedPanes(deps, root); + + // The item then advances — a second outcome must be recorded. + deps.getItemLifecycleState = vi.fn().mockResolvedValue({ id: 'WL-6', stage: 'plan_complete' }); + await monitorDispatchedPanes(deps, root); + + const outcomes = (await paneCloseEntries(root)).map((e) => e.outcome); + expect(outcomes).toEqual(['requires-attention', 'closed-as-plan-complete']); + }); + + it('does NOT act on unknown liveness when the item has not reached a terminal (fail-open)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-7', kind: 'plan', paneId: 'w1:p7', stage: 'intake_complete' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-7', stage: 'intake_complete' }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ ok: false, error: 'herdr down' }), + closePane, + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ checked: 1, logged: 0, closed: 0, errors: 0 }); + expect(closePane).not.toHaveBeenCalled(); + expect(await paneCloseEntries(root)).toEqual([]); + }); + + it('is fail-closed: a throwing closePane still logs the outcome (closed:false) and never throws (AC7)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-8', kind: 'intake', paneId: 'w1:p8', stage: 'idea' }); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-8', stage: 'intake_complete' }), + closePane: vi.fn().mockRejectedValue(new Error('herdr: pane not found')), + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ checked: 1, logged: 1, closed: 0, errors: 0 }); + expect((await paneCloseEntries(root))[0]).toMatchObject({ closed: false }); + }); + + it('is fail-closed: a throwing item lookup counts an error and never throws (AC7)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-9', kind: 'plan', paneId: 'w1:p9' }); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockRejectedValue(new Error('wl exploded')), + closePane: vi.fn().mockResolvedValue(true), + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ checked: 1, logged: 0, errors: 1 }); + }); + + it('continues past a bad pane so later panes still process (AC7)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-BAD', kind: 'plan', paneId: 'w1:pA' }); + await seedDispatch(root, { itemId: 'WL-GOOD', kind: 'intake', paneId: 'w1:pB' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn(async (itemId: string) => { + if (itemId === 'WL-BAD') throw new Error('wl exploded'); + return { id: itemId, stage: 'intake_complete' }; + }), + closePane, + }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ checked: 2, logged: 1, closed: 1, errors: 1 }); + expect(closePane).toHaveBeenCalledTimes(1); + expect(closePane).toHaveBeenCalledWith('w1:pB', root); + }); + + it('is a no-op when the item-state dep is absent (legacy callers)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-10', kind: 'plan', paneId: 'w1:p10', stage: 'intake_complete' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = makeDeps({ closePane }); + + const res = await monitorDispatchedPanes(deps, root); + + expect(res).toMatchObject({ checked: 0, logged: 0, closed: 0, errors: 0 }); + expect(closePane).not.toHaveBeenCalled(); + }); + + it('logs requires-attention for an item awaiting producer review (AC3)', async () => { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-11', kind: 'plan', paneId: 'w1:p11', stage: 'intake_complete' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ + id: 'WL-11', stage: 'intake_complete', needsProducerReview: true, + }), + closePane, + }); + + await monitorDispatchedPanes(deps, root); + + expect(closePane).toHaveBeenCalledWith('w1:p11', root); + expect((await paneCloseEntries(root))[0]).toMatchObject({ + outcome: 'requires-attention', + reasonCode: 'producer-review', + closed: true, + }); + }); +}); diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 807c57d6a..b212b5005 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -146,8 +146,18 @@ import { readDowntimeLogEntries as _readDowntimeEntries, dispatchedItemMarkers as _dispatchedMarkers, markerStillExcludes as _markerStillExcludes, + appendPaneCloseLogEntry as _appendPaneCloseLogEntry, type DispatchMarker, + type PaneCloseLogEntry, } from './downtime-log.js'; +import { + classifyPaneLifecycle, + collectDispatchedPanes, + loggedPaneLifecycleKeys, + paneLifecycleKey, + type DispatchedPane, + type PaneItemState, +} from './pane-lifecycle.js'; import { buildDowntimePaneTitle, MAX_PANE_TITLE_LENGTH } from './pane-title.js'; import type { DispatcherAnchor, DispatcherTabAnchorEntry } from './dispatcher-anchor.js'; @@ -271,6 +281,15 @@ export const DOWNTIME_AUDIT_STALE_WINDOW_MS = 2 * 60 * 60 * 1000; // 2 hours */ export const DEFAULT_DOWNTIME_MARKER_STALE_WINDOW_MS = 24 * 60 * 60 * 1000; +/** + * Pane-lifecycle monitor cadence (WL-0MU308WSF0002JWN): the worker re-checks + * dispatched panes for terminal states at most once per this interval, + * bounding the per-tick worklog queries ("reasonable polling cadence" — + * parent Constraint) while still closing completed panes promptly. Overridable + * per tick via the optional `paneLifecycleIntervalMs` config field. + */ +export const DOWNTIME_PANE_LIFECYCLE_INTERVAL_MS = 30_000; + /** * Hard floor for the success-marker staleness window (1 h): below this the * age release would fire while a dispatched pane is plausibly still running, @@ -1127,6 +1146,12 @@ export interface DowntimeItemInfo { * coordination leader path skips it (AC3). */ needsProducerReview?: boolean; + /** + * Recorded audit verdict (`auditResult.readyToClose` from `wl show + * --json`, WL-0MU308WSF0002JWN): `false` means the audit FAILED; `true` + * means it passed. Absent when the item has no recorded audit result. + */ + auditResult?: boolean | null; } /** @@ -1761,6 +1786,31 @@ export interface DowntimeWorkerDeps { * dispatcher swallows any rejection. */ recordDispatchEnrichment?(event: DowntimeDispatchEnrichmentEvent): Promise; + /** + * Pane-lifecycle item state lookup (WL-0MU308WSF0002JWN): resolve the + * current work-item state (stage/status/risk/effort/auditedAt/auditResult/ + * needsProducerReview) for a dispatched pane's item so the monitor can + * classify its lifecycle outcome. OPTIONAL — when absent the monitor + * cannot classify and takes no action (fail-open; production wiring always + * provides it). Must never throw; resolves null on a wl/CLI failure so a + * lookup failure never triggers a spurious close. + */ + getItemLifecycleState?(itemId: string, cwd: string): Promise; + /** + * Close a dispatched pane (WL-0MU308WSF0002JWN): `herdr pane close + * `. Resolves true on success, false on any failure. OPTIONAL — + * when absent the monitor logs the outcome but performs no close (used by + * legacy/test callers). Must never throw (fail-closed): a failed close is + * logged with `closed:false` and never blocks other panes. + */ + closePane?(paneId: string, cwd: string): Promise; + /** + * Record a pane-close lifecycle entry in the rolling dispatch log + * (WL-0MU308WSF0002JWN). OPTIONAL — when absent the monitor falls back to + * appending directly via `appendPaneCloseLogEntry`. Must never throw + * (fail-closed): logging must never crash the worker. + */ + recordPaneClose?(entry: PaneCloseLogEntry, cwd: string): Promise; /** * Roll back a CAS claim that succeeded but never completed dispatch * (WL-0MT32F908002YFFA AC1/AC2): restore the item to its pre-claim @@ -4251,6 +4301,134 @@ export async function spawnDowntimePane( }); } +// ── Pane-lifecycle monitor (WL-0MU308WSF0002JWN) ────────────────────── + +/** Summary of one pane-lifecycle monitor pass. */ +export interface PaneLifecycleMonitorResult { + /** Number of dispatched panes inspected. */ + checked: number; + /** Number of panes actually closed this pass. */ + closed: number; + /** Number of lifecycle outcomes logged this pass. */ + logged: number; + /** Number of per-pane failures swallowed (fail-closed). */ + errors: number; +} + +/** + * Inspect every dispatched pane recorded in the rolling log and, for each + * one that has reached a terminal or attention state, log a pane-close + * lifecycle entry and (except `implement`) close the pane + * (WL-0MU308WSF0002JWN). + * + * Fail-closed at every boundary (AC7): a missing log, an unreadable item, a + * failed pane close, or a failed log write is swallowed and never crashes + * the worker or blocks the remaining panes. Idempotent: a `(pane, outcome, + * reason)` triple already recorded in the log is never written twice, so + * repeated ticks (and multiple instances sharing a root) do not duplicate + * entries — while a genuine state CHANGE produces a new entry (intake Q&A). + * + * The monitor performs NO work when the deps are absent (legacy/test + * callers): with no `getItemLifecycleState` every pane classifies to null, + * so the pass is a cheap no-op. + */ +export async function monitorDispatchedPanes( + deps: DowntimeWorkerDeps, + cwd: string, +): Promise { + const result: PaneLifecycleMonitorResult = { checked: 0, closed: 0, logged: 0, errors: 0 }; + + // Strict no-op for legacy callers: without an item-state resolver the + // monitor cannot distinguish a terminal stage from "unknown", so taking + // any action (e.g. flagging requires-attention on agent-done alone) would + // be guesswork. Production wiring always provides the dep. + if (typeof deps.getItemLifecycleState !== 'function') return result; + + // Read the rolling log (fail-safe: unreadable → []). + let entries: Awaited>; + try { + entries = await _readDowntimeEntries(cwd); + } catch { + return result; // fail-closed: no evidence, no action + } + + const panes = collectDispatchedPanes(entries); + if (panes.length === 0) return result; + const loggedKeys = loggedPaneLifecycleKeys(entries); + + // Running-pane liveness: `null` when unknown (fail-open — an unknown + // liveness must never be read as "agent done", which would close a live + // pane). When known, a dispatched pane absent from the live set has ended. + let livePanes: Set | null = null; + if (typeof deps.getRunningDowntimePanes === 'function') { + try { + const running = await deps.getRunningDowntimePanes(cwd); + if (running.ok && Array.isArray(running.records)) { + livePanes = new Set(running.records.map((rec) => rec.paneId)); + } + } catch { + livePanes = null; // fail-open — never close on unknown liveness + } + } + + for (const pane of panes) { + result.checked += 1; + try { + let item: PaneItemState | null = null; + if (typeof deps.getItemLifecycleState === 'function') { + item = await deps.getItemLifecycleState(pane.itemId, cwd); + } + const agentDone = livePanes !== null && !livePanes.has(pane.paneId); + const decision = classifyPaneLifecycle(pane, item, agentDone); + if (decision === null) continue; + + const key = paneLifecycleKey(pane.paneId, decision.outcome, decision.reasonCode); + if (loggedKeys.has(key)) continue; // already recorded — idempotent + + // Close the pane (except `implement`, which is never auto-closed — + // AC6). A failed/absent close is recorded with `closed:false` and + // never blocks the log entry or the remaining panes (AC7). + let closed = false; + if (decision.close && typeof deps.closePane === 'function') { + try { + closed = await deps.closePane(pane.paneId, cwd); + } catch { + closed = false; // fail-closed + } + } + + const entry: PaneCloseLogEntry = { + entryType: 'pane-close', + timestamp: new Date().toISOString(), + itemId: pane.itemId, + itemTitle: item?.title ?? pane.itemTitle, + paneId: pane.paneId, + kind: pane.kind, + outcome: decision.outcome, + reason: decision.reason, + reasonCode: decision.reasonCode, + closed, + }; + try { + if (typeof deps.recordPaneClose === 'function') { + await deps.recordPaneClose(entry, cwd); + } else { + await _appendPaneCloseLogEntry(cwd, entry); + } + loggedKeys.add(key); + result.logged += 1; + if (closed) result.closed += 1; + } catch { + result.errors += 1; // fail-closed: logging must never crash the worker + } + } catch { + result.errors += 1; // fail-closed: one bad pane never blocks the rest + } + } + + return result; +} + // ── Worker orchestrator (implemented — F3) ──────────────────────────── /** @@ -4300,6 +4478,12 @@ export interface DowntimeWorkerConfig { * `DEFAULT_DOWNTIME_MARKER_STALE_WINDOW_MS` (24 h). */ markerStaleWindowMs?: number; + /** + * Pane-lifecycle monitor cadence, ms (WL-0MU308WSF0002JWN). Optional — + * defaults to `DOWNTIME_PANE_LIFECYCLE_INTERVAL_MS` (30 s). Tests may + * pass 0 to run the monitor on every tick. + */ + paneLifecycleIntervalMs?: number; }; /** * Optional shared round-robin registry (WL-0MSSRED76008LGB6) used for @@ -4444,6 +4628,9 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker const perSlotTracker = createPerSlotIdleTracker(); let dispatching = false; let lastDispatchAt: number | null = null; + // Pane-lifecycle monitor cadence gate (WL-0MU308WSF0002JWN): the timestamp + // of the last monitor pass. 0 forces a pass on the first tick. + let lastPaneMonitorAt = 0; // No-candidate cooldown (WL-0MSI7DQL10016QYX): timestamp until which the // worker is fully paused (no poll, no idle tracking, no dispatch) after a // genuine empty backlog OR three consecutive CLI errors. Cancelled early @@ -4788,6 +4975,29 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker } } + // ── Pane-lifecycle monitor (WL-0MU308WSF0002JWN) ────────────────── + // Runs on the LEADER (legacy mode: always) and BEFORE the cooldown + // gate, so completed dispatched panes are tidied even while dispatch + // is paused in a no-candidate cooldown. Cadence-bounded (default 30 s) + // so the ~10 s tick does not re-query the worklog for every open pane + // on every tick. + // + // FIRE-AND-FORGET (deliberately NOT awaited): the single-flight + // dispatch guard relies on the first in-flight tick setting + // `dispatching` before a second concurrent tick reaches its check — an + // extra await on the pre-dispatch path lets the second tick win that + // race and double-dispatch (pinned by the worker single-flight test). + // The monitor is internally fail-closed and idempotent, so running it + // concurrently is safe; the `.catch` is belt-and-braces. + const paneMonitorIntervalMs = + cfg.paneLifecycleIntervalMs ?? DOWNTIME_PANE_LIFECYCLE_INTERVAL_MS; + if (tickNow - lastPaneMonitorAt >= paneMonitorIntervalMs) { + lastPaneMonitorAt = tickNow; + void monitorDispatchedPanes(opts.deps, cfg.cwd).catch(() => { + // fail-closed: pane-lifecycle monitoring must never crash the worker + }); + } + // Cooldown gate (WL-0MTEZ4XZJ006Y9U7 AC2 — ordering): the check-in // block above runs FIRST, so a no-candidate pause never suppresses the // coordination check-in (the only mechanism that re-offers work once @@ -5955,6 +6165,17 @@ export function parseShowItemOutput(stdout: string): DowntimeItemInfo | null { needsProducerReview: raw.needsProducerReview !== undefined ? Boolean(raw.needsProducerReview) : undefined, }; + // Top-level audit result (WL-0MU308WSF0002JWN): `wl show --json` serves + // `auditResult` as a TOP-LEVEL sibling of `workItem` (not nested inside + // it), carrying the audit verdict (`readyToClose`) the pane-lifecycle + // monitor needs to distinguish audit-passed from audit-failed. Additive + // and tolerant — a missing/malformed auditResult leaves the fields absent. + const topAudit = (parsed as { auditResult?: unknown }).auditResult; + if (topAudit !== null && typeof topAudit === 'object') { + const a = topAudit as Record; + if (typeof a.auditedAt === 'string') info.auditedAt = a.auditedAt; + if (typeof a.readyToClose === 'boolean') info.auditResult = a.readyToClose; + } return info; } diff --git a/packages/herdr/src/index.ts b/packages/herdr/src/index.ts index 7ae004a1b..598d68e55 100644 --- a/packages/herdr/src/index.ts +++ b/packages/herdr/src/index.ts @@ -112,6 +112,7 @@ import { import { createRoundRobinRegistry, type RoundRobinRegistry } from './downtime-round-robin.js'; import { appendDowntimeLogEntry, + appendPaneCloseLogEntry, auditDispatchedItemIds, implementDispatchedItemIds, planDispatchedItemStages, @@ -1313,6 +1314,54 @@ export function createDowntimeDeps( // fail-open: enrichment logging must never crash the worker } }, + // Pane-lifecycle item state (WL-0MU308WSF0002JWN): resolve the current + // state of a dispatched pane's item so the monitor can classify its + // lifecycle outcome. Reuses the enriched `wl show` fetch (which now also + // carries the top-level audit verdict). Fail-closed: a wl failure or an + // unparseable item resolves null (the monitor then takes no action for + // that pane). Never throws. + async getItemLifecycleState(itemId: string, cwd: string) { + try { + const result = await fetchAuditItemById(itemId, cwd); + if (!result.ok || !result.info) return null; + const info = result.info; + return { + id: info.id, + title: info.title, + status: info.status, + stage: info.stage, + risk: info.risk, + effort: info.effort, + auditedAt: info.auditedAt, + auditResult: info.auditResult, + needsProducerReview: info.needsProducerReview, + }; + } catch { + return null; // fail-closed: an unreadable item is never acted upon + } + }, + // Close a dispatched pane (WL-0MU308WSF0002JWN): `herdr pane close + // `. Fail-closed: any herdr failure resolves false and the + // monitor still records the lifecycle outcome with `closed:false`. + async closePane(paneId: string, _cwd: string): Promise { + try { + const herdrBin = process.env.HERDR_BIN_PATH ?? 'herdr'; + await getExecFileAsync()( + herdrBin, + ['pane', 'close', paneId], + { encoding: 'utf8', timeout: DOWNTIME_WL_TIMEOUT_MS }, + ); + return true; + } catch { + return false; // fail-closed: a failed close must never crash the worker + } + }, + // Record a pane-close lifecycle entry in the rolling dispatch log + // (WL-0MU308WSF0002JWN). Fail-closed: `appendPaneCloseLogEntry` never + // throws. + async recordPaneClose(entry, cwd: string): Promise { + await appendPaneCloseLogEntry(cwd, entry); + }, async rollbackClaim( itemId: string, original: DowntimeClaimExpected, diff --git a/packages/herdr/src/pane-lifecycle.test.ts b/packages/herdr/src/pane-lifecycle.test.ts new file mode 100644 index 000000000..fa3f0ffd8 --- /dev/null +++ b/packages/herdr/src/pane-lifecycle.test.ts @@ -0,0 +1,212 @@ +/** + * Unit tests for pane-lifecycle.ts — the pure pane-lifecycle classifier and + * rolling-log collectors for the downtime worker's auto-close monitor + * (WL-0MU308WSF0002JWN, child WL-0MU4URK4H006OFCE). + * + * These tests pin the decision contract: which outcomes are produced, which + * kinds are auto-closed (everything except `implement` — AC6), and the + * idempotency keys that stop duplicate log entries. + */ + +import { describe, it, expect } from 'vitest'; +import { + shouldAutoClosePane, + collectDispatchedPanes, + loggedPaneLifecycleKeys, + paneLifecycleKey, + classifyPaneLifecycle, + type DispatchedPane, + type PaneItemState, +} from './pane-lifecycle.js'; +import type { DowntimeLogEntry } from './downtime-log.js'; + +function pane(overrides: Partial = {}): DispatchedPane { + return { + itemId: 'WL-1', + itemTitle: 'Test item', + paneId: 'w1:p1', + kind: 'plan', + dispatchedAt: '2026-01-01T00:00:00.000Z', + stage: 'intake_complete', + ...overrides, + }; +} + +function item(overrides: Partial = {}): PaneItemState { + return { id: 'WL-1', title: 'Test item', stage: 'intake_complete', ...overrides }; +} + +describe('shouldAutoClosePane (AC6 — implement is never auto-closed)', () => { + it('excludes implement and includes every other dispatch kind', () => { + expect(shouldAutoClosePane('implement')).toBe(false); + expect(shouldAutoClosePane('plan')).toBe(true); + expect(shouldAutoClosePane('intake')).toBe(true); + expect(shouldAutoClosePane('audit')).toBe(true); + expect(shouldAutoClosePane('risk-effort')).toBe(true); + }); +}); + +describe('collectDispatchedPanes', () => { + it('reconstructs panes from enrichment entries carrying a resolved paneId', () => { + const entries: DowntimeLogEntry[] = [ + { itemId: 'WL-1', kind: 'plan', title: 'Plan me', dispatchedAt: '2026-01-01T00:00:00.000Z', stage: 'intake_complete' }, + { itemId: 'WL-1', kind: 'plan', title: 'Plan me', dispatchedAt: '2026-01-01T00:00:00.000Z', stage: 'intake_complete', paneId: 'w1:p1', enrichment: true }, + ]; + const panes = collectDispatchedPanes(entries); + expect(panes).toHaveLength(1); + expect(panes[0]).toMatchObject({ itemId: 'WL-1', paneId: 'w1:p1', kind: 'plan', itemTitle: 'Plan me' }); + }); + + it('ignores entries without a paneId, without an itemId, of an unmanaged kind, or spawn-failed', () => { + const entries: DowntimeLogEntry[] = [ + { itemId: 'WL-1', kind: 'plan' }, // no paneId → not closeable + { kind: 'plan', paneId: 'w1:p2' }, // no itemId + { itemId: 'WL-3', kind: 'scheduled', paneId: 'w1:p3' }, // unmanaged kind + { itemId: 'WL-4', kind: 'audit', paneId: 'w1:p4', outcome: 'spawn-failed' }, // never appeared + { entryType: 'pane-close', paneId: 'w1:p5', itemId: 'WL-5' }, // lifecycle entry, not a dispatch + ]; + expect(collectDispatchedPanes(entries)).toEqual([]); + }); + + it('keeps the most recent entry per pane id', () => { + const entries: DowntimeLogEntry[] = [ + { itemId: 'WL-1', kind: 'plan', title: 'old', paneId: 'w1:p1', dispatchedAt: '2026-01-01T00:00:00.000Z' }, + { itemId: 'WL-1', kind: 'plan', title: 'new', paneId: 'w1:p1', dispatchedAt: '2026-01-02T00:00:00.000Z' }, + ]; + const panes = collectDispatchedPanes(entries); + expect(panes).toHaveLength(1); + expect(panes[0].itemTitle).toBe('new'); + expect(panes[0].dispatchedAt).toBe('2026-01-02T00:00:00.000Z'); + }); +}); + +describe('loggedPaneLifecycleKeys / paneLifecycleKey', () => { + it('collects the pane+outcome+reasonCode keys already recorded', () => { + const entries: DowntimeLogEntry[] = [ + { entryType: 'pane-close', paneId: 'w1:p1', outcome: 'closed-as-plan-complete', reasonCode: 'none' }, + { entryType: 'pane-close', paneId: 'w1:p2', outcome: 'requires-attention' }, // missing reasonCode → 'none' + { itemId: 'WL-1', kind: 'plan', paneId: 'w1:p3' }, // not a pane-close entry + ]; + const keys = loggedPaneLifecycleKeys(entries); + expect(keys.has(paneLifecycleKey('w1:p1', 'closed-as-plan-complete', 'none'))).toBe(true); + expect(keys.has(paneLifecycleKey('w1:p2', 'requires-attention', 'none'))).toBe(true); + expect(keys.size).toBe(2); + }); +}); + +describe('classifyPaneLifecycle — terminal close outcomes (AC2)', () => { + it('intake pane at intake_complete → closed-as-intake-complete (close)', () => { + const d = classifyPaneLifecycle(pane({ kind: 'intake' }), item({ stage: 'intake_complete' }), false); + expect(d).toMatchObject({ outcome: 'closed-as-intake-complete', close: true }); + }); + + it('plan pane at plan_complete → closed-as-plan-complete (close)', () => { + const d = classifyPaneLifecycle(pane({ kind: 'plan' }), item({ stage: 'plan_complete' }), false); + expect(d).toMatchObject({ outcome: 'closed-as-plan-complete', close: true }); + }); + + it('an intake pane whose item skipped ahead to plan_complete is still closed as intake-complete', () => { + const d = classifyPaneLifecycle(pane({ kind: 'intake' }), item({ stage: 'plan_complete' }), false); + expect(d).toMatchObject({ outcome: 'closed-as-intake-complete', close: true }); + }); + + it('risk-effort pane at plan_complete with risk+effort populated → closed-as-plan-complete (close)', () => { + const d = classifyPaneLifecycle( + pane({ kind: 'risk-effort' }), + item({ stage: 'plan_complete', risk: 'Low', effort: 'Small' }), + false, + ); + expect(d).toMatchObject({ outcome: 'closed-as-plan-complete', close: true }); + }); + + it('risk-effort pane at plan_complete WITHOUT risk/effort stays open while the agent runs', () => { + expect( + classifyPaneLifecycle(pane({ kind: 'risk-effort' }), item({ stage: 'plan_complete' }), false), + ).toBeNull(); + }); +}); + +describe('classifyPaneLifecycle — audit outcomes (AC5)', () => { + it('audit recorded + passed → audit-passed (close)', () => { + const d = classifyPaneLifecycle( + pane({ kind: 'audit' }), + item({ stage: 'in_review', auditedAt: '2026-01-02T00:00:00.000Z', auditResult: true }), + false, + ); + expect(d).toMatchObject({ outcome: 'audit-passed', close: true }); + }); + + it('audit recorded + failed → audit-failed (close)', () => { + const d = classifyPaneLifecycle( + pane({ kind: 'audit' }), + item({ stage: 'in_review', auditedAt: '2026-01-02T00:00:00.000Z', auditResult: false }), + false, + ); + expect(d).toMatchObject({ outcome: 'audit-failed', close: true }); + }); + + it('audit recorded with no explicit verdict defaults to passed', () => { + const d = classifyPaneLifecycle( + pane({ kind: 'audit' }), + item({ stage: 'in_review', auditedAt: '2026-01-02T00:00:00.000Z' }), + false, + ); + expect(d).toMatchObject({ outcome: 'audit-passed', close: true }); + }); + + it('audit pane whose agent ended without a result → requires-attention (close)', () => { + const d = classifyPaneLifecycle(pane({ kind: 'audit' }), item({ stage: 'in_review' }), true); + expect(d).toMatchObject({ outcome: 'requires-attention', reasonCode: 'audit-ended-no-result', close: true }); + }); + + it('audit pane still in flight → null', () => { + expect(classifyPaneLifecycle(pane({ kind: 'audit' }), item({ stage: 'in_review' }), false)).toBeNull(); + }); +}); + +describe('classifyPaneLifecycle — implement is logged but never closed (AC4/AC6)', () => { + it('implement pane at in_review → requires-attention, close:false', () => { + const d = classifyPaneLifecycle(pane({ kind: 'implement' }), item({ stage: 'in_review' }), false); + expect(d).toMatchObject({ outcome: 'requires-attention', reasonCode: 'reached-in-review', close: false }); + }); + + it('implement pane whose agent ended before in_review → requires-attention, close:false', () => { + const d = classifyPaneLifecycle(pane({ kind: 'implement' }), item({ stage: 'plan_complete' }), true); + expect(d).toMatchObject({ outcome: 'requires-attention', reasonCode: 'agent-ended-no-terminal', close: false }); + }); + + it('implement pane still running → null', () => { + expect(classifyPaneLifecycle(pane({ kind: 'implement' }), item({ stage: 'plan_complete' }), false)).toBeNull(); + }); +}); + +describe('classifyPaneLifecycle — requires-attention (AC3)', () => { + it('an item awaiting producer review → requires-attention (close)', () => { + const d = classifyPaneLifecycle( + pane({ kind: 'plan' }), + item({ stage: 'intake_complete', needsProducerReview: true }), + false, + ); + expect(d).toMatchObject({ outcome: 'requires-attention', reasonCode: 'producer-review', close: true }); + }); + + it('a plan agent that ended without reaching plan_complete → requires-attention (close)', () => { + const d = classifyPaneLifecycle(pane({ kind: 'plan' }), item({ stage: 'intake_complete' }), true); + expect(d).toMatchObject({ outcome: 'requires-attention', reasonCode: 'agent-ended-no-terminal', close: true }); + }); + + it('a risk-effort agent that ended without populating risk/effort → requires-attention (close)', () => { + const d = classifyPaneLifecycle(pane({ kind: 'risk-effort' }), item({ stage: 'plan_complete' }), true); + expect(d).toMatchObject({ outcome: 'requires-attention', reasonCode: 'risk-effort-incomplete', close: true }); + }); + + it('a still-working pane with no terminal → null (no action)', () => { + expect(classifyPaneLifecycle(pane({ kind: 'plan' }), item({ stage: 'intake_complete' }), false)).toBeNull(); + }); + + it('a missing item is tolerated (agent done → requires-attention, never a throw)', () => { + const d = classifyPaneLifecycle(pane({ kind: 'plan' }), null, true); + expect(d).toMatchObject({ outcome: 'requires-attention', close: true }); + expect(classifyPaneLifecycle(pane({ kind: 'plan' }), null, false)).toBeNull(); + }); +}); diff --git a/packages/herdr/src/pane-lifecycle.ts b/packages/herdr/src/pane-lifecycle.ts new file mode 100644 index 000000000..dd84c27dc --- /dev/null +++ b/packages/herdr/src/pane-lifecycle.ts @@ -0,0 +1,351 @@ +/** + * packages/herdr/src/pane-lifecycle.ts — Pane-lifecycle monitor (pure logic) + * + * Supporting logic for the downtime worker's automatic pane lifecycle + * management (WL-0MU308WSF0002JWN): dispatched panes stay open forever + * unless an operator closes them manually. This module classifies each + * dispatched pane's current state into a lifecycle outcome and decides + * whether the pane should be auto-closed (everything except `implement`, + * which is never auto-closed — AC6). + * + * The module is deliberately PURE (no fs / no herdr / no wl): the worker + * gathers the dispatch markers + current item states, this module decides, + * and the worker performs the log append + pane close. That keeps the + * decision logic trivially testable and the fail-closed I/O at the + * orchestration boundary. + * + * Outcomes (AC1): + * - `closed-as-intake-complete` — an `intake` pane's item reached + * `intake_complete` (or beyond). + * - `closed-as-plan-complete` — a `plan`/`risk-effort` pane's item reached + * `plan_complete` (risk-effort additionally requires risk+effort set). + * - `audit-passed` / `audit-failed` — an `audit` pane's item has a + * recorded audit result (`readyToClose`). + * - `requires-attention` — the pane ended (or is blocked) without reaching + * a closeable terminal: agent session ended early, an item awaiting + * producer review, an audit that never recorded a result, or an + * `implement` pane that reached `in_review` (logged, NOT closed — AC4). + */ + +import type { DowntimeLogEntry, PaneLifecycleKind } from './downtime-log.js'; + +// ── Types ───────────────────────────────────────────────────────────── + +/** + * Stable machine-readable reason for a lifecycle decision. Used as part of + * the idempotency key so a state CHANGE (e.g. `requires-attention` because + * the agent ended → `requires-attention` because the item later reached + * `in_review`) is logged again while a repeated identical state is not + * (intake Q&A: "if the pane is still open and the item changes again, log + * the new state"). + */ +export type PaneLifecycleReasonCode = + | 'none' + | 'agent-ended-no-terminal' + | 'reached-in-review' + | 'audit-ended-no-result' + | 'risk-effort-incomplete' + | 'producer-review'; + +/** + * One dispatched pane reconstructed from the rolling dispatch log. The + * enrichment entry (WL-0MUBVL251006JAQ0) records `paneId` alongside the + * marker fields; a dispatch with no enrichment (older entries, or a failed + * pane-id resolution) cannot be auto-closed. + */ +export interface DispatchedPane { + itemId: string; + itemTitle: string; + paneId: string; + kind: PaneLifecycleKind; + dispatchedAt: string; + /** Worklog stage at dispatch (change-guard marker). */ + stage?: string; +} + +/** + * The subset of the current work-item state the lifecycle classifier + * consults. Every field is optional / tolerant so a partially fetched or + * malformed item never throws. + */ +export interface PaneItemState { + id: string; + title?: string; + status?: string; + stage?: string; + risk?: string; + effort?: string; + auditedAt?: string | null; + /** + * Recorded audit verdict (`readyToClose`). `false` explicitly means the + * audit FAILED; `true`/`null`/absent (with an `auditedAt`) means passed + * (an audit with no recorded readyToClose is treated as a pass — the + * historical default, WL-0MTH7G2O1004BHN5). + */ + auditResult?: boolean | null; + needsProducerReview?: boolean; + /** Agent session state for the pane (idle/working/blocked/done/unknown). */ + agentState?: string; +} + +/** A decision for one dispatched pane. */ +export interface PaneLifecycleDecision { + outcome: import('./downtime-log.js').PaneLifecycleOutcome; + /** Human-readable summary reason (always populated). */ + reason: string; + /** Stable idempotency reason code. */ + reasonCode: PaneLifecycleReasonCode; + /** Whether the worker should close the pane. `false` only for `implement`. */ + close: boolean; +} + +// ── Constants ───────────────────────────────────────────────────────── + +/** Worklog stage rank — higher means further through the lifecycle. */ +const STAGE_RANK: Record = { + idea: 0, + intake_complete: 1, + plan_complete: 2, + in_review: 3, +}; + +/** The dispatch kinds the pane-lifecycle monitor manages. */ +const LIFECYCLE_KINDS: readonly PaneLifecycleKind[] = [ + 'plan', + 'intake', + 'audit', + 'risk-effort', + 'implement', +]; + +// ── Helpers ─────────────────────────────────────────────────────────── + +function isLifecycleKind(kind: unknown): kind is PaneLifecycleKind { + return typeof kind === 'string' && (LIFECYCLE_KINDS as readonly string[]).includes(kind); +} + +function stageRank(stage: string | undefined): number { + if (typeof stage !== 'string') return -1; + return STAGE_RANK[stage] ?? -1; +} + +/** + * AC6: `implement` panes are NEVER auto-closed — the operator closes them + * manually. Every other kind (plan / intake / audit / risk-effort) is + * auto-closed once its lifecycle outcome is determined. + */ +export function shouldAutoClosePane(kind: PaneLifecycleKind): boolean { + return kind !== 'implement'; +} + +/** + * Build the idempotency key for one (pane, outcome, reason) triple. A + * pane-close entry with a matching key suppresses a duplicate log entry on + * a later tick. + */ +export function paneLifecycleKey( + paneId: string, + outcome: string, + reasonCode: string, +): string { + return `${paneId}::${outcome}::${reasonCode}`; +} + +// ── Collection from the rolling log ─────────────────────────────────── + +/** + * Reconstruct the set of dispatched panes from the rolling dispatch log: + * every entry that carries BOTH an `itemId` and a resolved `paneId` of a + * managed kind. Spawn-failed entries are excluded (the pane never + * appeared). The LAST entry per pane id wins (a re-dispatch updates the + * marker), so the returned list holds at most one record per pane. + */ +export function collectDispatchedPanes(entries: DowntimeLogEntry[]): DispatchedPane[] { + const byPane = new Map(); + for (const e of entries) { + if (e.outcome === 'spawn-failed') continue; + if (!isLifecycleKind(e.kind)) continue; + if (typeof e.itemId !== 'string' || e.itemId === '') continue; + if (typeof e.paneId !== 'string' || e.paneId === '') continue; + byPane.set(e.paneId, { + itemId: e.itemId, + itemTitle: typeof e.title === 'string' && e.title !== '' ? e.title : e.itemId, + paneId: e.paneId, + kind: e.kind, + dispatchedAt: typeof e.dispatchedAt === 'string' ? e.dispatchedAt : '', + stage: typeof e.stage === 'string' ? e.stage : undefined, + }); + } + return [...byPane.values()]; +} + +/** + * Build the set of lifecycle keys already recorded in the log, so the + * monitor never writes a duplicate pane-close entry for an unchanged state. + */ +export function loggedPaneLifecycleKeys(entries: DowntimeLogEntry[]): Set { + const keys = new Set(); + for (const e of entries) { + if (e.entryType !== 'pane-close') continue; + if (typeof e.paneId !== 'string' || e.paneId === '') continue; + const outcome = typeof e.outcome === 'string' ? e.outcome : ''; + const reasonCode = typeof e.reasonCode === 'string' ? e.reasonCode : 'none'; + keys.add(paneLifecycleKey(e.paneId, outcome, reasonCode)); + } + return keys; +} + +// ── Classification ──────────────────────────────────────────────────── + +function decision( + kind: PaneLifecycleKind, + outcome: PaneLifecycleDecision['outcome'], + reason: string, + reasonCode: PaneLifecycleReasonCode, +): PaneLifecycleDecision { + return { outcome, reason, reasonCode, close: shouldAutoClosePane(kind) }; +} + +/** + * Classify one dispatched pane's lifecycle outcome from its current item + * state. Returns `null` when the pane has not yet reached any terminal or + * attention state (i.e. the agent is still legitimately working) — the + * caller logs/closes nothing this tick. + * + * `agentDone` is the authoritative "the pane's agent session has ended" + * signal (the pane is gone from `herdr agent list`, or reported `done`); + * it is passed explicitly so the pure classifier never queries herdr. + * + * Precedence (first match wins): + * 1. audit result recorded (`auditedAt`) → audit-passed/failed (AC5) + * 2. kind terminal reached → closed-as-* (AC2); for + * `implement` this is `in_review` and is logged only, never closed (AC4/AC6) + * 3. item awaiting producer review → requires-attention (AC3) + * 4. agent session ended without a terminal → requires-attention (AC3) + * 5. otherwise → null (still running) + */ +export function classifyPaneLifecycle( + dispatch: DispatchedPane, + item: PaneItemState | null, + agentDone: boolean, +): PaneLifecycleDecision | null { + const kind = dispatch.kind; + const title = item?.title ?? dispatch.itemTitle; + + // 1. Audit panes (AC5): complete when the item has a recorded audit. + if (kind === 'audit') { + if (item && typeof item.auditedAt === 'string' && item.auditedAt !== '') { + const passed = item.auditResult !== false; + return decision( + kind, + passed ? 'audit-passed' : 'audit-failed', + passed + ? `audit recorded for ${title} — passed` + : `audit recorded for ${title} — failed`, + 'none', + ); + } + if (item?.needsProducerReview === true) { + return decision( + kind, + 'requires-attention', + `${title} is awaiting producer review before the audit can complete`, + 'producer-review', + ); + } + if (agentDone) { + return decision( + kind, + 'requires-attention', + `audit agent session ended without recording an audit result for ${title}`, + 'audit-ended-no-result', + ); + } + return null; // audit still in flight + } + + // 2. Kind terminal reached. + if (item) { + const rank = stageRank(item.stage); + if (kind === 'intake' && rank >= stageRank('intake_complete')) { + return decision( + kind, + 'closed-as-intake-complete', + `${title} advanced to ${item.stage ?? 'intake_complete'} — intake complete`, + 'none', + ); + } + if (kind === 'plan' && rank >= stageRank('plan_complete')) { + return decision( + kind, + 'closed-as-plan-complete', + `${title} advanced to ${item.stage ?? 'plan_complete'} — plan complete`, + 'none', + ); + } + if (kind === 'risk-effort') { + const populated = + typeof item.risk === 'string' && item.risk !== '' && + typeof item.effort === 'string' && item.effort !== ''; + if (rank >= stageRank('plan_complete') && populated) { + return decision( + kind, + 'closed-as-plan-complete', + `${title} has risk/effort populated at ${item.stage ?? 'plan_complete'} — risk-effort complete`, + 'none', + ); + } + if (agentDone && rank >= stageRank('plan_complete') && !populated) { + return decision( + kind, + 'requires-attention', + `risk-effort agent session ended without populating risk/effort for ${title}`, + 'risk-effort-incomplete', + ); + } + if (agentDone) { + return decision( + kind, + 'requires-attention', + `risk-effort agent session ended before reaching plan_complete for ${title}`, + 'agent-ended-no-terminal', + ); + } + return null; + } + // implement (AC4/AC6): reaching in_review completes the implementation + // but the pane is NEVER auto-closed — log the event for the operator. + if (kind === 'implement' && rank >= stageRank('in_review')) { + return decision( + kind, + 'requires-attention', + `${title} reached in_review — implement panes are not auto-closed (AC6); close manually`, + 'reached-in-review', + ); + } + } + + // 3. Producer-review gate (AC3): a review-blocked item is not making + // progress — flag it so the pane does not linger silently. + if (item?.needsProducerReview === true) { + return decision( + kind, + 'requires-attention', + `${title} is awaiting producer review`, + 'producer-review', + ); + } + + // 4. Agent session ended without reaching a closeable terminal (AC3). + if (agentDone) { + return decision( + kind, + 'requires-attention', + `${title} agent session ended without reaching a terminal stage`, + 'agent-ended-no-terminal', + ); + } + + // 5. Still running. + return null; +} From 24b1e575e167ca3c18b23a9def1edd54c181d2b3 Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 16:07:56 +0100 Subject: [PATCH 04/20] WL-0MU4US5MP001JFEN: implement auto-close logic with implement exception --- packages/herdr/src/downtime-worker.test.ts | 114 ++++++++++++++++++++- packages/herdr/src/downtime-worker.ts | 36 ++++++- packages/herdr/src/index.ts | 26 ++++- 3 files changed, 168 insertions(+), 8 deletions(-) diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index 2a6ad1055..aa81335cb 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -107,6 +107,7 @@ import { parseHerdrPaneListOutput, countRunningDowntimePanes, paneLabelItemId, + isSafeDowntimePaneToClose, runningDowntimePaneItemIds, evaluateCriticalFirstGuard, resolveInFlightPanes, @@ -8081,6 +8082,21 @@ describe('paneLabelItemId / runningDowntimePaneItemIds / evaluateCriticalFirstGu expect(paneLabelItemId(undefined)).toBeNull(); }); + it('isSafeDowntimePaneToClose only accepts the downtime pane for the SAME item (AC7)', () => { + const live = [ + pane({ paneId: 'w1:p1', label: 'Downtime triggered implement Some item - WL-ABC' }), + pane({ paneId: 'w1:p2', label: 'pi - my operator session' }), + ]; + // Matching downtime pane for the item → safe. + expect(isSafeDowntimePaneToClose(live, 'w1:p1', 'WL-ABC')).toBe(true); + // A different item's downtime pane (id collision) → NOT safe. + expect(isSafeDowntimePaneToClose(live, 'w1:p1', 'WL-OTHER')).toBe(false); + // A non-downtime (operator) pane → NOT safe. + expect(isSafeDowntimePaneToClose(live, 'w1:p2', 'WL-ABC')).toBe(false); + // The pane is already gone → NOT safe (nothing to close). + expect(isSafeDowntimePaneToClose(live, 'w1:p9', 'WL-ABC')).toBe(false); + }); + it('runningDowntimePaneItemIds returns only WORKING downtime panes, keyed by item id', () => { const ids = runningDowntimePaneItemIds([ pane({ paneId: 'w1:p1', label: 'Downtime triggered implement A - WL-A', agentStatus: 'working' }), @@ -10204,7 +10220,7 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { const res = await monitorDispatchedPanes(deps, root); expect(res).toMatchObject({ checked: 1, logged: 1, closed: 1, errors: 0 }); - expect(closePane).toHaveBeenCalledWith('w1:p1', root); + expect(closePane).toHaveBeenCalledWith('w1:p1', root, { itemId: 'WL-1', kind: 'intake' }); const pc = await paneCloseEntries(root); expect(pc).toHaveLength(1); expect(pc[0]).toMatchObject({ @@ -10230,7 +10246,7 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { const res = await monitorDispatchedPanes(deps, root); expect(res).toMatchObject({ logged: 1, closed: 1 }); - expect(closePane).toHaveBeenCalledWith('w1:p2', root); + expect(closePane).toHaveBeenCalledWith('w1:p2', root, { itemId: 'WL-2', kind: 'plan' }); expect((await paneCloseEntries(root))[0]).toMatchObject({ outcome: 'closed-as-plan-complete', closed: true }); }); @@ -10248,7 +10264,7 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { const res = await monitorDispatchedPanes(deps, root); expect(res).toMatchObject({ logged: 1, closed: 1 }); - expect(closePane).toHaveBeenCalledWith('w1:p3', root); + expect(closePane).toHaveBeenCalledWith('w1:p3', root, { itemId: 'WL-3', kind: 'audit' }); expect((await paneCloseEntries(root))[0]).toMatchObject({ outcome: 'audit-failed', closed: true }); }); @@ -10372,7 +10388,7 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { expect(res).toMatchObject({ checked: 2, logged: 1, closed: 1, errors: 1 }); expect(closePane).toHaveBeenCalledTimes(1); - expect(closePane).toHaveBeenCalledWith('w1:pB', root); + expect(closePane).toHaveBeenCalledWith('w1:pB', root, { itemId: 'WL-GOOD', kind: 'intake' }); }); it('is a no-op when the item-state dep is absent (legacy callers)', async () => { @@ -10400,7 +10416,7 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { await monitorDispatchedPanes(deps, root); - expect(closePane).toHaveBeenCalledWith('w1:p11', root); + expect(closePane).toHaveBeenCalledWith('w1:p11', root, { itemId: 'WL-11', kind: 'plan' }); expect((await paneCloseEntries(root))[0]).toMatchObject({ outcome: 'requires-attention', reasonCode: 'producer-review', @@ -10408,3 +10424,91 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { }); }); }); + +// ── Worker tick ↔ pane-lifecycle integration (WL-0MU4US5MP001JFEN) ──── +// +// The worker tick invokes the pane-lifecycle monitor (fire-and-forget, so it +// never perturbs the dispatch single-flight ordering). These tests pin the +// end-to-end auto-close path and the mandatory implement exception (AC6). +describe('worker tick pane-lifecycle integration (WL-0MU4US5MP001JFEN)', () => { + const roots: string[] = []; + + afterEach(() => { + for (const root of roots.splice(0)) rmSync(root, { recursive: true, force: true }); + }); + + function makeRoot(): string { + const root = mkdtempSync(join(tmpdir(), 'pane-monitor-tick-')); + roots.push(root); + return root; + } + + async function seedDispatch(root: string, itemId: string, kind: string, paneId: string): Promise { + const marker = { + itemId, kind, dispatchedAt: new Date().toISOString(), cwd: root, title: itemId, stage: 'intake_complete', + }; + await appendDowntimeLogEntry(root, JSON.stringify(marker)); + await appendDowntimeLogEntry(root, JSON.stringify({ ...marker, paneId, enrichment: true })); + } + + function makeMonitorWorker(root: string, deps: Partial) { + const fetcher = vi.fn().mockResolvedValue(jsonResponseFixture(idleAllSlotsFree)); + const poller = createDowntimePoller('http://proxy:8000', fetcher); + const worker = createDowntimeWorker({ + poller, + deps: makeDeps({ getNextItem: vi.fn().mockResolvedValue({ ok: true, candidate: null }), ...deps }), + config: () => ({ + enabled: true, + thresholdMs: 1, + requiredFreeSlots: 0, + model: 'plan', + cwd: root, + noCandidateCooldownMs: 3_600_000, + paneLifecycleIntervalMs: 0, + }), + }); + return worker; + } + + it('closes a completed non-implement pane from the worker tick (AC1/AC2)', async () => { + const root = makeRoot(); + await seedDispatch(root, 'WL-TICK', 'plan', 'w9:p1'); + const closePane = vi.fn().mockResolvedValue(true); + const worker = makeMonitorWorker(root, { + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-TICK', stage: 'plan_complete' }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ ok: true, count: 1, records: [{ paneId: 'w9:p1' }] }), + closePane, + }); + + await worker.tick(); + + await vi.waitFor(() => expect(closePane).toHaveBeenCalledWith( + 'w9:p1', root, { itemId: 'WL-TICK', kind: 'plan' }, + )); + const pc = (await readDowntimeLogEntries(root)).filter((e) => e.entryType === 'pane-close'); + expect(pc).toHaveLength(1); + expect(pc[0]).toMatchObject({ outcome: 'closed-as-plan-complete', closed: true }); + }); + + it('never auto-closes an implement pane from the worker tick (AC6)', async () => { + const root = makeRoot(); + await seedDispatch(root, 'WL-IMPL', 'implement', 'w9:p2'); + const closePane = vi.fn().mockResolvedValue(true); + const worker = makeMonitorWorker(root, { + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-IMPL', stage: 'in_review' }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ ok: true, count: 1, records: [{ paneId: 'w9:p2' }] }), + closePane, + }); + + await worker.tick(); + + // Wait for the (fire-and-forget) monitor to record the in_review event. + await vi.waitFor(async () => { + const pc = (await readDowntimeLogEntries(root)).filter((e) => e.entryType === 'pane-close'); + expect(pc).toHaveLength(1); + }); + expect(closePane).not.toHaveBeenCalled(); + const pc = (await readDowntimeLogEntries(root)).filter((e) => e.entryType === 'pane-close'); + expect(pc[0]).toMatchObject({ outcome: 'requires-attention', reasonCode: 'reached-in-review', closed: false }); + }); +}); diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index b212b5005..2b414d471 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -1350,6 +1350,29 @@ export function paneLabelItemId(label: string | undefined): string | null { return id === '' ? null : id; } +/** + * Safe-close predicate (WL-0MU4US5MP001JFEN AC7): true ONLY when a LIVE herdr + * pane record exists for `paneId`, its label is a downtime pane label + * (`DOWNTIME_PANE_LABEL_PREFIX`) AND its item-id suffix equals `itemId`. + * + * Guarding the close with this predicate means a stale dispatch-log entry can + * never close an unrelated/operator pane whose pane id happens to collide with + * the recorded dispatched pane (pane ids may be reused after a pane closes). + * A missing record (the pane is already gone) returns false — there is nothing + * to close. + */ +export function isSafeDowntimePaneToClose( + records: HerdrPaneRecord[], + paneId: string, + itemId: string, +): boolean { + const rec = records.find((p) => p.paneId === paneId); + if (rec === undefined) return false; + const label = rec.label ?? ''; + if (!label.startsWith(DOWNTIME_PANE_LABEL_PREFIX)) return false; + return paneLabelItemId(label) === itemId; +} + /** * Item ids that currently have a LIVE `working` downtime pane * (WL-0MUBEZ6PE002WLP4, the in-flight guard). @@ -1802,8 +1825,17 @@ export interface DowntimeWorkerDeps { * when absent the monitor logs the outcome but performs no close (used by * legacy/test callers). Must never throw (fail-closed): a failed close is * logged with `closed:false` and never blocks other panes. + * + * `expected` (optional, WL-0MU4US5MP001JFEN AC7) carries the dispatch + * context so an implementation can verify the live pane really is the + * downtime pane spawned for THIS item before closing it — never close an + * unrelated/operator pane whose id happens to collide with a stale entry. */ - closePane?(paneId: string, cwd: string): Promise; + closePane?( + paneId: string, + cwd: string, + expected?: { itemId: string; kind: PaneLifecycleKind }, + ): Promise; /** * Record a pane-close lifecycle entry in the rolling dispatch log * (WL-0MU308WSF0002JWN). OPTIONAL — when absent the monitor falls back to @@ -4391,7 +4423,7 @@ export async function monitorDispatchedPanes( let closed = false; if (decision.close && typeof deps.closePane === 'function') { try { - closed = await deps.closePane(pane.paneId, cwd); + closed = await deps.closePane(pane.paneId, cwd, { itemId: pane.itemId, kind: pane.kind }); } catch { closed = false; // fail-closed } diff --git a/packages/herdr/src/index.ts b/packages/herdr/src/index.ts index 598d68e55..832f2515d 100644 --- a/packages/herdr/src/index.ts +++ b/packages/herdr/src/index.ts @@ -101,6 +101,7 @@ import { withTransientRetry, parseHerdrPaneListOutput, countRunningDowntimePanes, + isSafeDowntimePaneToClose, type RunningPanesResult, type LlamaStatus, } from './downtime-worker.js'; @@ -1343,9 +1344,32 @@ export function createDowntimeDeps( // Close a dispatched pane (WL-0MU308WSF0002JWN): `herdr pane close // `. Fail-closed: any herdr failure resolves false and the // monitor still records the lifecycle outcome with `closed:false`. - async closePane(paneId: string, _cwd: string): Promise { + // + // Safety (WL-0MU4US5MP001JFEN AC7): when the dispatch context is + // supplied, verify the LIVE pane's label is a downtime pane whose + // item-id suffix matches THIS dispatch BEFORE closing — a stale entry + // must never close an unrelated/operator pane whose pane id collides. + async closePane( + paneId: string, + _cwd: string, + expected?: { itemId: string; kind: string }, + ): Promise { try { const herdrBin = process.env.HERDR_BIN_PATH ?? 'herdr'; + if (expected) { + const { stdout } = await getExecFileAsync()( + herdrBin, + ['pane', 'list'], + { encoding: 'utf8', timeout: DOWNTIME_WL_TIMEOUT_MS, maxBuffer: 4 * 1024 * 1024 }, + ); + const panes = parseHerdrPaneListOutput(stdout); + // Only ever close a downtime pane for THIS item (AC7). A missing + // record (pane already gone) or a mismatched label means we must + // NOT close (never an unrelated/operator pane id collision). + if (panes === null || !isSafeDowntimePaneToClose(panes, paneId, expected.itemId)) { + return false; + } + } await getExecFileAsync()( herdrBin, ['pane', 'close', paneId], From 191f634e86a4a28a0b918abc095221ef5e8e1829 Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 16:05:12 +0100 Subject: [PATCH 05/20] WL-0MU88086A0089US4: Implementation complete --- .../herdr/src/downtime-worker.fixtures.ts | 3 + packages/herdr/src/downtime-worker.test.ts | 66 +++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 57 ++++++++++++---- 3 files changed, 115 insertions(+), 11 deletions(-) diff --git a/packages/herdr/src/downtime-worker.fixtures.ts b/packages/herdr/src/downtime-worker.fixtures.ts index e64dc1ca7..7c19069de 100644 --- a/packages/herdr/src/downtime-worker.fixtures.ts +++ b/packages/herdr/src/downtime-worker.fixtures.ts @@ -22,6 +22,9 @@ export const idleAllSlotsFree: LlamaStatus = { available_slots: 4, total_slots: 4, current_model: 'qwen3-8b', + // Normalised owner-session list (WL-0MU88086A0089US4): always present on + // the parsed status, empty when the proxy reports no owner. + local_owner_session_ids: [], }; export const busyActiveQuery: LlamaStatus = { ...idleAllSlotsFree, local_active_query: true }; diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index aa81335cb..7a957c411 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -9853,6 +9853,72 @@ describe('parseLlamaStatus: array local_owner_session_id (WL-0MU88086A0089US4)', }); }); +describe('parseLlamaStatus: local_owner_session_ids normalization (WL-0MU88086A0089US4)', () => { + function makeBase(): Record { + return { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 3, + total_slots: 3, + contention_queue_depth: 0, + contention_queued_count: 0, + }; + } + + it('captures every session in the array and drops the proxy URL element', () => { + const result = parseLlamaStatus({ + ...makeBase(), + local_owner_session_id: ['http://localhost:8080', 'session-a', 'session-b'], + }); + expect(result).not.toBeNull(); + expect(result!.local_owner_session_ids).toEqual(['session-a', 'session-b']); + expect(result!.local_owner_session_id).toBe('session-a'); + }); + + it('normalises a legacy string owner to a single-element array', () => { + const result = parseLlamaStatus({ + ...makeBase(), + local_owner_session_id: 'legacy-session', + }); + expect(result).not.toBeNull(); + expect(result!.local_owner_session_ids).toEqual(['legacy-session']); + expect(result!.local_owner_session_id).toBe('legacy-session'); + }); + + it('yields an empty owner list for malformed input (fail-closed, no throw)', () => { + const malformedInputs: unknown[] = [ + 42, + { id: 'bad' }, + [], + ['http://localhost:8080'], + [42], + ['http://localhost:8080', 42], + ]; + for (const malformed of malformedInputs) { + const result = parseLlamaStatus({ + ...makeBase(), + local_owner_session_id: malformed, + }); + expect(result).not.toBeNull(); + expect(result!.local_owner_session_ids).toEqual([]); + expect(result!.local_owner_session_id).toBeUndefined(); + } + }); + + it('marks local_lease_active from a multi-session array even without lease seconds', () => { + const result = parseLlamaStatus({ + ...makeBase(), + local_lease_active: undefined, + local_owner_session_id: ['http://localhost:8080', 'session-a', 'session-b'], + }); + expect(result).not.toBeNull(); + expect(result!.local_lease_active).toBe(true); + }); +}); + // ── Per-slot owner-lease gate in tick() (WL-0MU8807BI008C9ME AC1-AC4) ── describe('tick(): owner-lease gate must be per-slot (WL-0MU8807BI008C9ME)', () => { diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 2b414d471..799254f39 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -440,6 +440,15 @@ export interface LlamaStatus { total_slots: number; current_model?: string; local_owner_session_id?: string | null; + /** + * Every owner session id reported by the proxy, normalised across the + * legacy string form and the current array form (WL-0MU88086A0089US4): + * array elements that are HTTP(S) URLs (the proxy's own base URL, e.g. + * `"http://localhost:8080"`) are excluded, and a legacy string yields a + * single-element array. Empty when no owner is reported. Kept alongside + * `local_owner_session_id` (the first id) for backward compatibility. + */ + local_owner_session_ids?: string[]; local_owner_lease_remaining_seconds?: number | null; /** * Proxy-reported LIVE contention queue depth (AC6, parent @@ -752,23 +761,47 @@ export const DEFAULT_DOWNTIME_POLL_TIMEOUT_MS = 5_000; * malformed/negative (ambiguous → the caller fails closed to busy). */ /** - * Extract the owner session ID from `local_owner_session_id`, accepting both - * the legacy string form and the current array form + * True for an HTTP(S) URL element of the proxy's owner array. The live proxy + * serves `local_owner_session_id` as `["http://localhost:8080", ""]` + * where the first element is its own base URL, NOT an owner session. + */ +function isOwnerUrlElement(value: string): boolean { + return /^https?:\/\//i.test(value); +} + +/** + * Normalise `local_owner_session_id` into the FULL list of owner session ids, + * accepting both the legacy string form and the current array form * `["http://localhost:8080", "herdr-"]`. * - * Returns the session string (2nd element of the array) for array inputs, - * the string itself for string inputs, and `undefined` for any malformed - * input (number, object, empty array, etc.) — fail-closed. + * Array elements that are HTTP(S) URLs (the proxy's own base URL) are not + * owners and are dropped; every non-empty non-URL string element is retained + * so a multi-owner payload is never silently truncated (contributing cause 1 + * of RCA WL-0MU87ZGPP0029V28). A legacy string yields a single-element array. + * Malformed input (number, object, `null`, array of non-strings) yields `[]` + * — fail-closed, never throws. * * (WL-0MU88086A0089US4 — parse array local_owner_session_id from llama-proxy) */ -function parseLocalOwnerSessionId(value: unknown): string | undefined { - if (typeof value === 'string' && value.length > 0) return value; - if (Array.isArray(value) && value.length >= 2) { - const session = value[1]; - if (typeof session === 'string' && session.length > 0) return session; +function parseLocalOwnerSessionIds(value: unknown): string[] { + if (typeof value === 'string' && value.length > 0) return [value]; + if (Array.isArray(value)) { + return value.filter( + (el): el is string => + typeof el === 'string' && el.length > 0 && !isOwnerUrlElement(el), + ); } - return undefined; + return []; +} + +/** + * The first (primary) owner session id — kept for compatibility with existing + * call sites (`local_lease_active` derivation, `ownerLeaseHeld`). Returns + * `undefined` when no owner session is reported. See + * {@link parseLocalOwnerSessionIds}. + */ +function parseLocalOwnerSessionId(value: unknown): string | undefined { + return parseLocalOwnerSessionIds(value)[0]; } function parseOptionalCount(value: unknown): number | undefined | null { @@ -899,6 +932,8 @@ export function parseLlamaStatus(raw: unknown): LlamaStatus | null { current_model: typeof o.current_model === 'string' ? o.current_model : undefined, local_owner_session_id: parseLocalOwnerSessionId(o.local_owner_session_id), + local_owner_session_ids: + parseLocalOwnerSessionIds(o.local_owner_session_id), local_owner_lease_remaining_seconds: typeof o.local_owner_lease_remaining_seconds === 'number' ? o.local_owner_lease_remaining_seconds From f2d31cbf7aa70d36e55c9b0fefdb9cbe2323a5c6 Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 16:21:35 +0100 Subject: [PATCH 06/20] WL-0MU8808ZY0091JIA: log no-dispatch decision reason and surface held gate in header Make "idle slots but no dispatches" diagnosable from logs and the header. - downtime-log.ts: extend CoordinationLogEntry with additive decision fields (reason/freeSlots/totalSlots/ownerPresent/runningPanes/contentionDepth) and add readCoordinationLogEntries() (fail-safe reader). - downtime-worker.ts: record a kind:'decision'/operation:'no-dispatch' entry in .worklog/downtime-coordination.log when a polled tick is refused by the slot-owned or contention gates, or by an actionable dispatch outcome (no-candidate/review-queue-hold/code-freeze/audit-in-flight/wl-error/...). Identical repeated refusals are rate-limited to one line per 10 minutes (DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS, <=6/hour); a reason change logs immediately. Expose readonly blockReason (short header token) via decisionHeaderToken(). New optional deps.recordDecision for tests. - worklist.ts: renderDowntimeStatus shows `[downtime held: ]` when a gate blocked the last tick, distinct from the idle/busy labels. - Tests: decision-log AC1-AC3, header-token mapping, and header render tests. --- packages/herdr/src/downtime-log.ts | 44 ++++++ packages/herdr/src/downtime-worker.test.ts | 163 +++++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 136 ++++++++++++++++- packages/herdr/src/worklist.test.ts | 22 +++ packages/herdr/src/worklist.ts | 10 ++ 5 files changed, 374 insertions(+), 1 deletion(-) diff --git a/packages/herdr/src/downtime-log.ts b/packages/herdr/src/downtime-log.ts index de828a0c9..6ef2eff0c 100644 --- a/packages/herdr/src/downtime-log.ts +++ b/packages/herdr/src/downtime-log.ts @@ -52,6 +52,19 @@ export interface CoordinationLogEntry { workItemId?: string | null; /** Number of entries removed by a prune operation. */ prunedCount?: number; + /** + * No-dispatch decision fields (WL-0MU8808ZY0091JIA): recorded on a + * `kind: 'decision'` / `operation: 'no-dispatch'` entry so the reason a + * tick refused to dispatch is observable from the log alone. All optional + * so coordination check-in/election entries are unchanged (additive + * schema). + */ + reason?: string; + freeSlots?: number; + totalSlots?: number; + ownerPresent?: boolean; + runningPanes?: number | null; + contentionDepth?: number; at?: string; } @@ -239,6 +252,37 @@ export async function readDowntimeLogEntries(cwd: string): Promise/.worklog/downtime-coordination.log` (WL-0MU8808ZY0091JIA). Same + * FAIL-SAFE contract as `readDowntimeLogEntries`: a missing or unreadable + * log yields `[]`, malformed JSONL lines are skipped, and the function never + * throws. Used by the decision-log tests and any observer that wants the + * dispatcher's refusal reasons without parsing the file by hand. + */ +export async function readCoordinationLogEntries(cwd: string): Promise { + const file = join(cwd, '.worklog', COORDINATION_LOG_FILE); + let raw: string; + try { + raw = await readFile(file, 'utf8'); + } catch { + return []; // missing or unreadable → empty (fail-safe) + } + const entries: CoordinationLogEntry[] = []; + for (const line of raw.split('\n')) { + if (line.trim() === '') continue; + try { + const parsed = JSON.parse(line) as unknown; + if (typeof parsed === 'object' && parsed !== null) { + entries.push(parsed as CoordinationLogEntry); + } + } catch { + // malformed line → skip (fail-safe) + } + } + return entries; +} + /** * True for a rolling-log line that participates in the dispatched-marker * readers. Pane-lifecycle close entries (`entryType: 'pane-close'`, diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index 7a957c411..fa217b856 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -142,6 +142,8 @@ import { MIN_BROWSE_ITEM_COUNT, MAX_BROWSE_ITEM_COUNT, DOWNTIME_DISPATCH_EXTEND_MAX, + DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS, + decisionHeaderToken, } from './downtime-worker.js'; import { clampBrowseItemCount, @@ -158,6 +160,8 @@ import { appendDowntimeLogEntry, appendPaneCloseLogEntry, readDowntimeLogEntries, + readCoordinationLogEntries, + type CoordinationLogEntry, } from './downtime-log.js'; import { LEASE_FILE, @@ -10578,3 +10582,162 @@ describe('worker tick pane-lifecycle integration (WL-0MU4US5MP001JFEN)', () => { expect(pc[0]).toMatchObject({ outcome: 'requires-attention', reasonCode: 'reached-in-review', closed: false }); }); }); + +// ── No-dispatch decision log + header (WL-0MU8808ZY0091JIA) ────────── + +describe('downtime no-dispatch decision log (WL-0MU8808ZY0091JIA)', () => { + function makeDecisionWorker(opts: { + status: LlamaStatus; + root: string; + requiredFreeSlots?: number; + thresholdMs?: number; + runningPanes?: () => { ok: true; count: number } | { ok: false; error?: string }; + recordDecision?: (entry: CoordinationLogEntry, cwd: string) => Promise; + }) { + const cfg = { + enabled: true, + thresholdMs: opts.thresholdMs ?? 0, + requiredFreeSlots: opts.requiredFreeSlots ?? 0, + model: 'plan', + cwd: opts.root, + noCandidateCooldownMs: 3_600_000, + browseItemCount: 20, + }; + const poller = createDowntimePoller( + 'http://proxy:8000', + vi.fn().mockResolvedValue(jsonResponseFixture(opts.status)), + ); + const deps = makeDeps({ + getNextItem: vi.fn().mockResolvedValue({ ok: true, candidate: null }), + getRunningDowntimePanes: vi + .fn() + .mockImplementation(async () => (opts.runningPanes ?? (() => ({ ok: true, count: 0 })))()), + ...(opts.recordDecision ? { recordDecision: opts.recordDecision } : {}), + }); + const worker = createDowntimeWorker({ poller, deps, config: () => ({ ...cfg }) }); + return { worker, deps }; + } + + it('maps internal reasons to stable header tokens', () => { + expect(decisionHeaderToken('slot-owned')).toBe('slot-owner'); + expect(decisionHeaderToken('proxy-contention')).toBe('contention'); + expect(decisionHeaderToken('review-queue-hold')).toBe('review-queue'); + expect(decisionHeaderToken('code-freeze')).toBe('code-freeze'); + }); + + it('AC1: a slot-owned refusal writes one decision line with reason + slot/owner fields', async () => { + const root = mkdtempSync(join(tmpdir(), 'herdr-decision-slot-')); + try { + // Count-based (no `slots`), idle (local_lease_active=false) but the + // global owner session id is present and a downtime pane is alive → + // slotOwned. + const status: LlamaStatus = { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 1, + total_slots: 1, + local_owner_session_id: 'session-live-pane', + contention_queue_depth: 0, + contention_queued_count: 0, + }; + const { worker } = makeDecisionWorker({ + status, + root, + runningPanes: () => ({ ok: true, count: 1 }), + }); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(false); + expect(worker.blockReason).toBe('slot-owner'); + await vi.waitFor(async () => { + const entries = (await readCoordinationLogEntries(root)).filter( + (e) => e.kind === 'decision', + ); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + kind: 'decision', + operation: 'no-dispatch', + reason: 'slot-owned', + freeSlots: 1, + totalSlots: 1, + ownerPresent: true, + runningPanes: 1, + contentionDepth: 0, + }); + expect(typeof entries[0].at).toBe('string'); + }); + } finally { + rmSync(root, { recursive: true, force: true }); + } + }); + + it('AC2: a contention refusal writes the reason and the observed depth', async () => { + const root = mkdtempSync(join(tmpdir(), 'herdr-decision-contention-')); + try { + const status: LlamaStatus = { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 1, + total_slots: 1, + contention_queue_depth: 3, + contention_queued_count: 3, + }; + const { worker } = makeDecisionWorker({ status, root }); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(false); + expect(worker.blockReason).toBe('contention'); + await vi.waitFor(async () => { + const entries = (await readCoordinationLogEntries(root)).filter( + (e) => e.kind === 'decision', + ); + expect(entries).toHaveLength(1); + expect(entries[0]).toMatchObject({ + reason: 'proxy-contention', + contentionDepth: 3, + ownerPresent: false, + }); + }); + } finally { + rmSync(root, { recursive: true, force: true }); + } + }); + + it('AC3: repeated identical refusals are rate-limited, then logged again after the window', async () => { + const root = mkdtempSync(join(tmpdir(), 'herdr-decision-rate-')); + vi.useFakeTimers(); + try { + const status: LlamaStatus = { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 1, + total_slots: 1, + contention_queue_depth: 3, + contention_queued_count: 3, + }; + const recordDecision = vi.fn().mockResolvedValue(undefined); + const { worker } = makeDecisionWorker({ status, root, recordDecision }); + const start = 1_000_000; + vi.setSystemTime(start); + await worker.tick(); // first refusal → logged + expect(recordDecision).toHaveBeenCalledTimes(1); + vi.setSystemTime(start + 60_000); // 1 min later, same reason → suppressed + await worker.tick(); + expect(recordDecision).toHaveBeenCalledTimes(1); + // Past the rate-limit window → logged again (≤ 6 identical lines/hour). + vi.setSystemTime(start + DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS + 1); + await worker.tick(); + expect(recordDecision).toHaveBeenCalledTimes(2); + } finally { + vi.useRealTimers(); + rmSync(root, { recursive: true, force: true }); + } + }); +}); diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 799254f39..593614b48 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -141,7 +141,7 @@ import { cleanupStaleElection, DEFAULT_LEASE_TTL_SECONDS, } from './leader-election.js'; -import { appendCoordinationLogEntry } from './downtime-log.js'; +import { appendCoordinationLogEntry, type CoordinationLogEntry } from './downtime-log.js'; import { readDowntimeLogEntries as _readDowntimeEntries, dispatchedItemMarkers as _dispatchedMarkers, @@ -211,6 +211,34 @@ export const DOWNTIME_AUDIT_MIN_FREE_SLOTS = 2; */ export const DOWNTIME_PANE_MIN_FREE_SLOTS = 1; +/** + * Minimum interval between identical no-dispatch decision-log entries + * (WL-0MU8808ZY0091JIA AC3): a healthy idle/gate-blocked loop must not flood + * `.worklog/downtime-coordination.log`. A repeated refusal with the SAME + * reason is suppressed until this window elapses; a reason CHANGE is always + * logged immediately. 10 minutes → at most 6 identical lines per hour. + */ +export const DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS = 10 * 60_000; + +/** + * Short, stable header token for a no-dispatch reason (WL-0MU8808ZY0091JIA + * AC4). Distinct from the plain idle/busy labels so "idle slots but no + * dispatches" is visible in the herdr header. The RAW reason is what gets + * logged; only the header label is abbreviated. + */ +export function decisionHeaderToken(reason: string): string { + switch (reason) { + case 'slot-owned': + return 'slot-owner'; + case 'proxy-contention': + return 'contention'; + case 'review-queue-hold': + return 'review-queue'; + default: + return reason; + } +} + /** Sane floor for the no-candidate cooldown (the pause cannot be disabled or set trivially small). */ export const DOWNTIME_NO_CANDIDATE_COOLDOWN_FLOOR_MS = 60_000; @@ -1905,6 +1933,16 @@ export interface DowntimeWorkerDeps { * Must never throw (fail-closed): logging must not crash the worker. */ recordError(event: DowntimeErrorEvent): Promise; + /** + * Record one no-dispatch DECISION entry (WL-0MU8808ZY0091JIA) — the reason + * a polled tick refused to dispatch (slot-owner / contention / no-candidate + * / review-queue-hold / code-freeze / ...), with the observed slot/owner + * fields. Optional: when absent the worker appends directly to + * `.worklog/downtime-coordination.log` (the production default). Tests + * inject a spy to assert the decision vocabulary and rate-limiting without + * touching the filesystem. Fail-closed: a throw is swallowed. + */ + recordDecision?(entry: CoordinationLogEntry, cwd: string): Promise; } /** Audit event recorded for every successful downtime dispatch. */ @@ -4623,6 +4661,14 @@ export interface DowntimeWorker { readonly dispatching: boolean; /** Timestamp of the last successful dispatch (null until the first). */ readonly lastDispatchAt: number | null; + /** + * Short token for the gate that blocked the last polled tick (e.g. + * `'slot-owner'`, `'contention'`, `'code-freeze'`), or null when the worker + * was not gate-blocked (idle/busy/dispatching/disabled). Powers the header's + * `[downtime held: ]` label so "idle slots but no dispatches" is + * visible (WL-0MU8808ZY0091JIA AC4). + */ + readonly blockReason: string | null; /** * Whether the worker is enabled per the current settings (re-read) AND the * per-instance in-memory override: effective enabled = `override ?? @@ -4707,6 +4753,12 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // Three-strike rule: consecutive CLI-error dispatch outcomes. A successful // dispatch, a genuine no-candidate outcome, or an expired cooldown resets it. let errorStrikes = 0; + // No-dispatch decision logging (WL-0MU8808ZY0091JIA): the last reason + // written and when, so repeated identical refusals are rate-limited. + let lastDecisionReason: string | null = null; + let lastDecisionAt = 0; + // Current header blocking token; null when not gate-blocked. Reset each tick. + let blockReason: string | null = null; // Per-instance in-memory enabled override (parent WL-0MSZ4NSOE007AQEF): // null (default) = follow the global setting; true/false force dispatch // on/off for THIS instance. In-memory only — resets on plugin restart, @@ -4822,6 +4874,54 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker } }; + // ── No-dispatch decision log (WL-0MU8808ZY0091JIA) ── + // Record WHY a polled tick refused to dispatch so "idle slots but no + // dispatches" is diagnosable from the logs alone. Rate-limited: a repeated + // refusal with the SAME reason is written at most once per + // DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS; a reason CHANGE always writes. The + // header blocking token is updated on EVERY refusal (even a rate-limited + // one) so the header never goes stale. Fail-closed: a logging failure never + // affects the dispatch decision. + const recordDecision = async ( + cwd: string, + reason: string, + fields: { + freeSlots: number; + totalSlots: number; + ownerPresent: boolean; + runningPanes: number | null; + contentionDepth: number; + }, + ): Promise => { + blockReason = decisionHeaderToken(reason); + const now = Date.now(); + if ( + lastDecisionReason === reason && + now - lastDecisionAt < DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS + ) { + return; // rate-limited: identical refusal within the window + } + lastDecisionReason = reason; + lastDecisionAt = now; + const entry: CoordinationLogEntry = { + kind: 'decision', + operation: 'no-dispatch', + instanceId, + reason, + ...fields, + at: new Date(now).toISOString(), + }; + try { + if (typeof opts.deps.recordDecision === 'function') { + await opts.deps.recordDecision(entry, cwd); + } else { + await appendCoordinationLogEntry(cwd, entry); + } + } catch { + // fail-closed: decision logging must never crash the worker + } + }; + return { get idleSince(): number | null { return tracker.idleSince; @@ -4881,8 +4981,14 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker get errorStrikes(): number { return errorStrikes; }, + get blockReason(): string | null { + return blockReason; + }, async tick(): Promise { const cfg = opts.config(); + // Fresh per-tick decision state: clear the header blocking reason; a + // gate below re-sets it when this tick is refused (WL-0MU8808ZY0091JIA). + blockReason = null; // Short-circuit on the EFFECTIVE enabled state (override ?? settings): // while toggled off the worker performs no proxy polling, no idle // tracking, and no dispatch — exactly the settings-disabled path. @@ -5269,9 +5375,23 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // concurrency limiter, and a liveness-query failure no longer blocks // dispatch (it only feeds the `slotOwned` qualifier). if (slotOwned) { + void recordDecision(cfg.cwd, 'slot-owned', { + freeSlots, + totalSlots: status.total_slots, + ownerPresent: ownerLeaseHeld, + runningPanes, + contentionDepth: contentionQueueDepth, + }); return { polled: true, dispatched: false, idle: true }; } if (contentionQueueDepth > 0) { + void recordDecision(cfg.cwd, 'proxy-contention', { + freeSlots, + totalSlots: status.total_slots, + ownerPresent: ownerLeaseHeld, + runningPanes, + contentionDepth: contentionQueueDepth, + }); return { polled: true, dispatched: false, idle: true }; } @@ -5320,6 +5440,20 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker markerStaleWindowMs: cfg.markerStaleWindowMs, spawnConfig, }); + // Record the refusal reason (WL-0MU8808ZY0091JIA): actionable + // no-dispatch outcomes (no-candidate / review-queue-hold / code-freeze + // / audit-in-flight / wl-error / ...) are logged (rate-limited) so the + // dispatcher's decision is observable. A successful dispatch is not a + // refusal. + if (!outcome.dispatched && typeof outcome.reason === 'string') { + void recordDecision(cfg.cwd, outcome.reason, { + freeSlots, + totalSlots: status.total_slots, + ownerPresent: ownerLeaseHeld, + runningPanes, + contentionDepth: contentionQueueDepth, + }); + } if (outcome.dispatched) { lastDispatchAt = Date.now(); errorStrikes = 0; // a successful dispatch proves the CLI is healthy diff --git a/packages/herdr/src/worklist.test.ts b/packages/herdr/src/worklist.test.ts index 22b715ac4..77db68970 100644 --- a/packages/herdr/src/worklist.test.ts +++ b/packages/herdr/src/worklist.test.ts @@ -3291,6 +3291,28 @@ describe('renderDowntimeStatus', () => { expect(status).not.toContain('downtime idle'); }); + it('renders the held reason when a gate blocked the last tick (WL-0MU8808ZY0091JIA)', () => { + const worker = { + idleSince: Date.now() - 60_000, + dispatching: false, + enabled: true, + blockReason: 'slot-owner', + } as unknown as DowntimeWorker; + const status = renderDowntimeStatus(worker); + expect(status).toContain('downtime held: slot-owner'); + expect(status).not.toContain('downtime idle'); + }); + + it('renders plain idle when no gate blocked the last tick', () => { + const worker = { + idleSince: Date.now() - 60_000, + dispatching: false, + enabled: true, + blockReason: null, + } as unknown as DowntimeWorker; + expect(renderDowntimeStatus(worker)).toContain('downtime idle'); + }); + it('renders busy when the proxy is not idle', () => { const worker = { idleSince: null, diff --git a/packages/herdr/src/worklist.ts b/packages/herdr/src/worklist.ts index 51789ae25..36f39ced6 100644 --- a/packages/herdr/src/worklist.ts +++ b/packages/herdr/src/worklist.ts @@ -3286,6 +3286,10 @@ export function handleMouseInput( * `[Downtime Off (restored)]` (disable restored from the persisted marker, * WL-0MT5SG0VU005ARUR), or `[downtime paused]` (no-candidate cooldown, * WL-0MSI7DQL10016QYX). + * `[downtime held: ]` (WL-0MU8808ZY0091JIA) shows the gate that + * refused the last polled tick (e.g. `slot-owner`, `contention`, + * `code-freeze`) so "idle slots but no dispatches" is visible instead of a + * misleading idle label. * `[Downtime Off]` replaces the legacy `[downtime disabled]` text and is * shown whenever dispatch is off for the instance — either globally * settings-disabled or toggled off via the `d` shortcut (parent @@ -3315,6 +3319,12 @@ export function renderDowntimeStatus(worker: DowntimeWorker | undefined): string // duration (AC6, WL-0MSI7DQL10016QYX). return ` ${ANSI.dim}[downtime paused]${ANSI.reset}`; } + if (worker.blockReason) { + // A gate refused the last polled tick (slot-owner / contention / + // code-freeze / ...). Distinct from the idle label so the operator can + // see WHY idle slots are not being used (WL-0MU8808ZY0091JIA AC4). + return ` ${ANSI.fg(208)}[downtime held: ${worker.blockReason}]${ANSI.reset}`; + } if (worker.idleSince !== null) { const elapsedSecs = Math.max(0, Math.floor((Date.now() - worker.idleSince) / 1000)); const minutes = Math.floor(elapsedSecs / 60); From 7bfc2c014de0eadb0776a1528297a2065b7e9f07 Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 16:29:43 +0100 Subject: [PATCH 07/20] WL-0MU8809SZ0022VZG: correct proxy lease-TTL assumption; own-pane leases don't block free slots Replace the false "~180 s lease" assumption with the real cross-repo contract. - downtime-worker.ts: add LOCAL_DISPATCH_LEASE_MAX_SECONDS = 1500 (the llm-manager proxy's adaptive local_dispatch_lease_max_seconds default) and rewrite the slotOwned comment to state the lease is adaptive and can be held for a whole generation (observed 836 s -> 0). Document that the dispatcher does not wait out leases; the per-slot gate is what stops a dispatched pane's own lease blocking other free unowned slots. - docs/dev/downtime-dispatcher.md: record the proxy lease contract and the cross-repo llm-manager dependency so the assumption cannot drift silently. - Tests: pin the constant; a max-TTL unknown/operator lease on a count-based single slot still refuses (no optimistic expiry); a max-TTL lease held by a dispatched pane does not block the free unowned slots (per-slot). --- docs/dev/downtime-dispatcher.md | 24 +++- packages/herdr/src/downtime-worker.test.ts | 121 +++++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 30 ++++- 3 files changed, 167 insertions(+), 8 deletions(-) diff --git a/docs/dev/downtime-dispatcher.md b/docs/dev/downtime-dispatcher.md index 461168943..1e314ffee 100644 --- a/docs/dev/downtime-dispatcher.md +++ b/docs/dev/downtime-dispatcher.md @@ -720,12 +720,26 @@ an agent on a tool call (wl, bash, tests) left the slot "free", so multiple 1. **Owner-lease gate (AC2)** — a non-null Local Proxy owner lease (`local_owner_session_id` / `local_owner_lease_remaining_seconds`) counts as "slot busy" for the dispatch decision when the worker has a live - dispatch pane; only a truly unowned slot is dispatchable. The lease - signal **self-heals**: proxy dispatch leases carry an `expires_at` - (~180 s, `_get_lease_timeout_seconds`) refreshed on activity, are marked - inactive when a stream ends, and expired records are cleaned up — so an - idle-but-open pane stops holding a slot. + dispatch pane; only a truly unowned slot is dispatchable. Dispatch outcome reason: `slot-owned`. + + **Lease contract (WL-0MU8809SZ0022VZG; cross-repo dependency: + `llm-manager`).** The lease is **adaptive**, NOT a fixed ~180 s. The + implementation lives in `llm-manager` (`proxy/proxy/router_helpers.py`): + it extends a static base in proportion to the generation and caps it at + `local_dispatch_lease_max_seconds` (**default 1500 s**), with chunk/prefill + refresh buffers keeping it alive while a stream is active. A long agent + generation therefore holds the lease for its **whole run** — the RCA + observed a dispatched-pane lease run 836 s → 0 (WL-0MU87ZGPP0029V28). + The dispatcher does **not** wait out a lease: it dispatches into genuinely + free **unowned** slots via the per-slot gate (WL-0MU8807BI008C9ME), and a + lease held by a dispatched pane (which already owns its own slot) does not + block the OTHER free unowned slots. Only the **count-based single-slot** + path treats a held lease as blocking (a truly owned sole slot stays + protected). The maximum is pinned in code as + `LOCAL_DISPATCH_LEASE_MAX_SECONDS`; if `llm-manager` changes the default, + revisit that constant and this section so the assumption cannot drift + silently again. 2. **Per-slot owner tracking (AC5)** — `LlamaSlot` carries an optional `owner_session_id`; `countFreeUnownedSlots` excludes owned slots from the free count and the per-slot idle tracker resets an owned slot's timer, so diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index fa217b856..029d0e84c 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -144,6 +144,7 @@ import { DOWNTIME_DISPATCH_EXTEND_MAX, DOWNTIME_DECISION_LOG_MIN_INTERVAL_MS, decisionHeaderToken, + LOCAL_DISPATCH_LEASE_MAX_SECONDS, } from './downtime-worker.js'; import { clampBrowseItemCount, @@ -10741,3 +10742,123 @@ describe('downtime no-dispatch decision log (WL-0MU8808ZY0091JIA)', () => { } }); }); + +// ── Local dispatch-lease TTL + own-pane leases (WL-0MU8809SZ0022VZG) ── + +describe('local dispatch-lease TTL + own-pane leases (WL-0MU8809SZ0022VZG)', () => { + function makeLeaseWorker(opts: { + status: LlamaStatus; + requiredFreeSlots: number; + thresholdMs?: number; + runningPanes: number; + }) { + const cfg = { + enabled: true, + thresholdMs: opts.thresholdMs ?? 0, + requiredFreeSlots: opts.requiredFreeSlots, + model: 'plan', + cwd: '/repo', + noCandidateCooldownMs: 3_600_000, + browseItemCount: 20, + }; + const poller = createDowntimePoller( + 'http://proxy:8000', + vi.fn().mockResolvedValue(jsonResponseFixture(opts.status)), + ); + const deps = makeDeps({ + getNextItem: vi.fn().mockResolvedValue({ + ok: true, + candidate: { id: 'WL-ABC', title: 'Some task', stage: 'intake_complete' }, + }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ + ok: true, + count: opts.runningPanes, + paneIds: [], + records: [], + }), + }); + const worker = createDowntimeWorker({ poller, deps, config: () => ({ ...cfg }) }); + return { worker, deps }; + } + + it('AC1: pins the proxy adaptive lease maximum (llm-manager default 1500 s)', () => { + // The proxy lease is adaptive and capped at local_dispatch_lease_max_seconds + // (default 1500 s) — NOT the historical ~180 s the code used to assume. + expect(LOCAL_DISPATCH_LEASE_MAX_SECONDS).toBe(1500); + }); + + it('AC1/AC3: a max-TTL unknown/operator lease on a count-based single slot still refuses dispatch', async () => { + // The dispatcher must not optimistically assume the lease expired: a lease + // at the proxy MAX on a count-based single-slot setup (an unknown/operator + // owner) keeps blocking while a downtime pane is alive. local_lease_active + // is false so the idle gate passes and the slot-owned gate is the blocker. + const status: LlamaStatus = { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 1, + total_slots: 1, + local_owner_session_id: 'operator-session', + local_owner_lease_remaining_seconds: LOCAL_DISPATCH_LEASE_MAX_SECONDS, + contention_queue_depth: 0, + contention_queued_count: 0, + }; + const { worker, deps } = makeLeaseWorker({ + status, + requiredFreeSlots: 0, + runningPanes: 1, + }); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(false); + expect(worker.blockReason).toBe('slot-owner'); + expect(deps.spawnAgentPane).not.toHaveBeenCalled(); + }); + + it('AC2: a max-TTL lease held by a dispatched pane does not block the free unowned slots (per-slot)', async () => { + // Self-blocking case (RCA WL-0MU87ZGPP0029V28): the dispatched pane owns + // slot-1; slots 2 and 3 are free and unowned. Even with the lease at the + // proxy MAX and the worker's own pane alive, dispatch into the free slots + // MUST proceed — the per-slot gate ignores the global lease when unowned + // slots remain. + vi.useFakeTimers(); + try { + const ownSession = 'dispatched-pane-session'; + const status: LlamaStatus = { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: true, + available_slots: 2, + total_slots: 3, + local_owner_session_id: ['http://localhost:8080', ownSession], + local_owner_session_ids: [ownSession], + local_owner_lease_remaining_seconds: LOCAL_DISPATCH_LEASE_MAX_SECONDS, + slots: [ + { slot_id: 'slot-1', is_processing: true, owner_session_id: ownSession }, + { slot_id: 'slot-2', is_processing: false }, + { slot_id: 'slot-3', is_processing: false }, + ], + contention_queue_depth: 0, + contention_queued_count: 0, + }; + const { worker, deps } = makeLeaseWorker({ + status, + requiredFreeSlots: 2, + thresholdMs: 1_000, + runningPanes: 1, + }); + const start = 1_000_000; + vi.setSystemTime(start); + await worker.tick(); // baseline — start the per-slot idle timers + vi.setSystemTime(start + 5_000); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(true); + expect(deps.spawnAgentPane).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }); +}); diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 593614b48..998b48c5b 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -425,6 +425,26 @@ export const DEFAULT_COORDINATION_CHECK_IN_MS = 5 * 60 * 1000; */ export const DEFAULT_LEADER_CHECK_IN_MS = 4 * 60 * 1000; +/** + * Maximum local DISPATCH-lease TTL (seconds) the llama-proxy can hold a + * local slot — the cross-repo contract from `llm-manager` + * (`proxy/proxy/router_helpers.py`, WL-0MU8809SZ0022VZG). + * + * The lease is ADAPTIVE, not a fixed ~180 s: a static base plus + * generation-proportional extension, capped at + * `local_dispatch_lease_max_seconds` (default 1500 s), with chunk/prefill + * refresh buffers that keep it alive while a stream is active. A long agent + * generation therefore holds the lease for its WHOLE run — the RCA observed a + * dispatched-pane lease run 836 s → 0 (WL-0MU87ZGPP0029V28). + * + * The dispatcher MUST NOT assume leases expire after ~180 s. It does not WAIT + * OUT a lease: it dispatches into genuinely free UNOWNED slots (the per-slot + * gate, WL-0MU8807BI008C9ME) and only the count-based single-slot path treats + * a held lease as blocking. If `llm-manager` changes the default, revisit + * this constant and `docs/dev/downtime-dispatcher.md`. + */ +export const LOCAL_DISPATCH_LEASE_MAX_SECONDS = 1500; + /** * Retired coordination tier ordering (parent AC4 → WL-0MTK1ILM2009QYB2). * The coordination leader no longer re-ranks offers by tier: it dispatches @@ -5345,9 +5365,13 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // `slotOwned` is qualified on a known running-pane count > 0 so an // OPERATOR lease on a spare-capacity multi-slot setup does not block // dispatch into the free slots when the worker has no running pane - // of its own. (The lease signal self-heals: proxy leases expire ~180 s - // after activity stops — router_helpers.py `_get_lease_timeout_seconds` - // — so an idle-but-open pane does not block dispatch indefinitely.) + // of its own. The lease is NOT short-lived: the proxy holds an + // ADAPTIVE lease up to `LOCAL_DISPATCH_LEASE_MAX_SECONDS` (default + // 1500 s, cross-repo `llm-manager`), so an idle-but-open pane CAN block + // the count-based path for its whole run — the historical "~180 s" + // assumption was wrong (WL-0MU8809SZ0022VZG). The per-slot path + // (WL-0MU8807BI008C9ME) is what keeps a dispatched pane's own lease + // from blocking the OTHER free unowned slots. const ownerLeaseHeld = (parseLocalOwnerSessionId(status.local_owner_session_id) !== undefined) || (typeof status.local_owner_lease_remaining_seconds === 'number' && From 69e873173f36ab84310e36318799305777abeece Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 16:21:44 +0100 Subject: [PATCH 08/20] WL-0MU4USJ07009JYL8: add fail-closed error handling and comprehensive pane-lifecycle tests --- packages/herdr/src/downtime-worker.test.ts | 77 ++++++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 43 ++++++++++-- 2 files changed, 113 insertions(+), 7 deletions(-) diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index 029d0e84c..1219094ee 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -10494,6 +10494,83 @@ describe('pane-lifecycle monitor (WL-0MU308WSF0002JWN)', () => { closed: true, }); }); + + // ── Warn-level observability (WL-0MU4USJ07009JYL8 AC2/AC6) ────────── + // Every fail-closed catch must emit a stderr warn (never silent) so a + // production failure is diagnosable without a debugger. + function stderrMessages(spy: ReturnType): string { + return spy.mock.calls.map((c) => String(c[0])).join('\n'); + } + + it('warns on a failed pane close (AC2)', async () => { + const spy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + try { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-W1', kind: 'intake', paneId: 'w1:pW1' }); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-W1', stage: 'intake_complete' }), + closePane: vi.fn().mockRejectedValue(new Error('herdr: boom')), + }); + await monitorDispatchedPanes(deps, root); + expect(stderrMessages(spy)).toContain('pane close failed for w1:pW1'); + } finally { + spy.mockRestore(); + } + }); + + it('warns on a failed item lookup (AC2)', async () => { + const spy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + try { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-W2', kind: 'plan', paneId: 'w1:pW2' }); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockRejectedValue(new Error('wl exploded')), + }); + await monitorDispatchedPanes(deps, root); + expect(stderrMessages(spy)).toContain('item lookup failed for WL-W2'); + } finally { + spy.mockRestore(); + } + }); + + it('warns on a failed pane-close log write (AC2)', async () => { + const spy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + try { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-W3', kind: 'plan', paneId: 'w1:pW3' }); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-W3', stage: 'plan_complete' }), + closePane: vi.fn().mockResolvedValue(true), + recordPaneClose: vi.fn().mockRejectedValue(new Error('disk full')), + }); + const res = await monitorDispatchedPanes(deps, root); + expect(res).toMatchObject({ logged: 0, errors: 1 }); + expect(stderrMessages(spy)).toContain('pane-close log write failed for w1:pW3'); + } finally { + spy.mockRestore(); + } + }); + + it('warns when the live-pane query fails (AC2) and still fails open', async () => { + const spy = vi.spyOn(process.stderr, 'write').mockImplementation(() => true); + try { + const root = makeRoot(); + await seedDispatch(root, { itemId: 'WL-W4', kind: 'plan', paneId: 'w1:pW4' }); + const closePane = vi.fn().mockResolvedValue(true); + const deps = monitorDeps({ + getItemLifecycleState: vi.fn().mockResolvedValue({ id: 'WL-W4', stage: 'plan_complete' }), + getRunningDowntimePanes: vi.fn().mockRejectedValue(new Error('herdr down')), + closePane, + }); + const res = await monitorDispatchedPanes(deps, root); + // The terminal-stage close still happens (liveness is only needed for + // agent-done detection) — fail-open, not fail-closed, on liveness. + expect(res).toMatchObject({ logged: 1, closed: 1 }); + expect(stderrMessages(spy)).toContain('live-pane query threw'); + } finally { + spy.mockRestore(); + } + }); }); // ── Worker tick ↔ pane-lifecycle integration (WL-0MU4US5MP001JFEN) ──── diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 998b48c5b..37358ecef 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -4457,6 +4457,23 @@ export interface PaneLifecycleMonitorResult { * callers): with no `getItemLifecycleState` every pane classifies to null, * so the pass is a cheap no-op. */ +/** + * Warn-level observability for pane-lifecycle failures + * (WL-0MU4USJ07009JYL8 AC2). Fail-closed: a stderr write failure is + * swallowed — observability must never crash the worker. + */ +function paneLifecycleWarn(message: string): void { + try { + process.stderr.write(`[worklog-plugin] Downtime pane-lifecycle: ${message}\n`); + } catch { + // fail-closed: logging must never crash the worker + } +} + +function paneLifecycleErrMsg(err: unknown): string { + return err instanceof Error ? err.message : String(err); +} + export async function monitorDispatchedPanes( deps: DowntimeWorkerDeps, cwd: string, @@ -4473,7 +4490,8 @@ export async function monitorDispatchedPanes( let entries: Awaited>; try { entries = await _readDowntimeEntries(cwd); - } catch { + } catch (err) { + paneLifecycleWarn(`could not read the dispatch log — skipping this pass: ${paneLifecycleErrMsg(err)}`); return result; // fail-closed: no evidence, no action } @@ -4490,8 +4508,11 @@ export async function monitorDispatchedPanes( const running = await deps.getRunningDowntimePanes(cwd); if (running.ok && Array.isArray(running.records)) { livePanes = new Set(running.records.map((rec) => rec.paneId)); + } else if (!running.ok) { + paneLifecycleWarn('live-pane query failed — skipping agent-done detection this pass'); } - } catch { + } catch (err) { + paneLifecycleWarn(`live-pane query threw — skipping agent-done detection this pass: ${paneLifecycleErrMsg(err)}`); livePanes = null; // fail-open — never close on unknown liveness } } @@ -4500,8 +4521,12 @@ export async function monitorDispatchedPanes( result.checked += 1; try { let item: PaneItemState | null = null; - if (typeof deps.getItemLifecycleState === 'function') { + try { item = await deps.getItemLifecycleState(pane.itemId, cwd); + } catch (err) { + paneLifecycleWarn(`item lookup failed for ${pane.itemId} (pane ${pane.paneId}): ${paneLifecycleErrMsg(err)}`); + result.errors += 1; + continue; // fail-closed: no evidence → take no action for this pane } const agentDone = livePanes !== null && !livePanes.has(pane.paneId); const decision = classifyPaneLifecycle(pane, item, agentDone); @@ -4517,7 +4542,8 @@ export async function monitorDispatchedPanes( if (decision.close && typeof deps.closePane === 'function') { try { closed = await deps.closePane(pane.paneId, cwd, { itemId: pane.itemId, kind: pane.kind }); - } catch { + } catch (err) { + paneLifecycleWarn(`pane close failed for ${pane.paneId} (${pane.itemId}): ${paneLifecycleErrMsg(err)}`); closed = false; // fail-closed } } @@ -4543,10 +4569,12 @@ export async function monitorDispatchedPanes( loggedKeys.add(key); result.logged += 1; if (closed) result.closed += 1; - } catch { + } catch (err) { + paneLifecycleWarn(`pane-close log write failed for ${pane.paneId} (${pane.itemId}): ${paneLifecycleErrMsg(err)}`); result.errors += 1; // fail-closed: logging must never crash the worker } - } catch { + } catch (err) { + paneLifecycleWarn(`lifecycle pass failed for pane ${pane.paneId}: ${paneLifecycleErrMsg(err)}`); result.errors += 1; // fail-closed: one bad pane never blocks the rest } } @@ -5186,8 +5214,9 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker cfg.paneLifecycleIntervalMs ?? DOWNTIME_PANE_LIFECYCLE_INTERVAL_MS; if (tickNow - lastPaneMonitorAt >= paneMonitorIntervalMs) { lastPaneMonitorAt = tickNow; - void monitorDispatchedPanes(opts.deps, cfg.cwd).catch(() => { + void monitorDispatchedPanes(opts.deps, cfg.cwd).catch((err) => { // fail-closed: pane-lifecycle monitoring must never crash the worker + paneLifecycleWarn(`monitor pass threw: ${paneLifecycleErrMsg(err)}`); }); } From 227cbe112712013da486ebe9cb622e9c2ca67d5a Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 17:49:18 +0100 Subject: [PATCH 09/20] WL-0MUFRFLRQ004KNDG: fix plugin init TDZ crash on modeSwitchWorker The worklist plugin crashed at startup (prefix+l): ReferenceError: Cannot access 'modeSwitchWorker' before initialization at Object.config (index.ts:1611) at createDowntimeWorker (downtime-worker.ts:4821) at main (index.ts:1583) createDowntimeWorker calls config() SYNCHRONOUSLY during construction (the durable-disable marker check), but index.ts's config closure referenced the `modeSwitchWorker` const declared AFTER the downtime worker -> temporal dead zone. Introduced by 6188a90d (added the mode field) + 88a14451 (moved the mode-switch worker after the downtime worker). Fix: read the last-known mode through the existing `modeSwitchHolder`, which is declared before the downtime worker. It is empty at construction (conservative undefined -> PARALLELISM=1) and populated immediately after, so later ticks read the real mode. No TDZ. Adds packages/herdr/src/plugin-startup.test.ts: an end-to-end startup guard that runs `npx tsx src/index.ts` and asserts it reaches the TUI without the init error (verified red before the fix, green after). --- packages/herdr/src/index.ts | 11 ++- packages/herdr/src/plugin-startup.test.ts | 81 +++++++++++++++++++++++ 2 files changed, 91 insertions(+), 1 deletion(-) create mode 100644 packages/herdr/src/plugin-startup.test.ts diff --git a/packages/herdr/src/index.ts b/packages/herdr/src/index.ts index 832f2515d..1c9487853 100644 --- a/packages/herdr/src/index.ts +++ b/packages/herdr/src/index.ts @@ -1608,7 +1608,16 @@ async function main(): Promise { // Mode-aware Phase 2 parallelism (WL-0MT50S9JW001DHME): the last // proxy mode observed by the mode-switch worker (`null` until polled // → `undefined` → the dispatcher conservatively keeps PARALLELISM=1). - mode: modeSwitchWorker.getLastKnownMode() ?? undefined, + // + // WL-0MUFRFLRQ004KNDG: read through `modeSwitchHolder`, NOT the + // `modeSwitchWorker` const below. createDowntimeWorker calls config() + // SYNCHRONOUSLY during construction (the durable-disable marker check), + // which runs before `modeSwitchWorker` is initialized — referencing it + // directly hit the temporal dead zone and crashed the whole plugin at + // startup. The holder is declared above; it is empty at construction + // (conservative `undefined` → PARALLELISM=1) and populated immediately + // after, so later ticks read the real mode. + mode: modeSwitchHolder.worker?.getLastKnownMode() ?? undefined, noCandidateCooldownMs: s.downtimeNoCandidateCooldownMs, // Dispatched success-marker staleness window (WL-0MU6UL0RJ008IHGT). markerStaleWindowMs: s.downtimeMarkerStaleWindowMs, diff --git a/packages/herdr/src/plugin-startup.test.ts b/packages/herdr/src/plugin-startup.test.ts new file mode 100644 index 000000000..2f1f30777 --- /dev/null +++ b/packages/herdr/src/plugin-startup.test.ts @@ -0,0 +1,81 @@ +/** + * Plugin startup regression test (WL-0MUFRFLRQ004KNDG). + * + * The worklist plugin crashed on initialization with a temporal-dead-zone + * ReferenceError: `createDowntimeWorker` calls its `config()` callback + * SYNCHRONOUSLY during construction, and index.ts's callback referenced the + * `modeSwitchWorker` const that is declared AFTER the downtime worker — so + * the whole plugin died before the TUI ever rendered. + * + * This is an end-to-end guard: it runs the real entry point (the same command + * herdr's pane manifest uses, `npx tsx src/index.ts`) and asserts it reaches + * the TUI instead of crashing during wiring. + */ + +import { describe, it, expect } from 'vitest'; +import { spawn } from 'node:child_process'; +import { fileURLToPath } from 'node:url'; + +interface StartupResult { + code: number | null; + output: string; +} + +/** Run the plugin entry point and resolve with its combined output. */ +function runPluginStartup(cwd: string, timeoutMs: number): Promise { + return new Promise((resolve) => { + const child = spawn('npx', ['tsx', 'src/index.ts'], { + cwd, + // stdin is closed so the TUI tears down instead of blocking on input. + stdio: ['ignore', 'pipe', 'pipe'], + env: { ...process.env, HERDR_PANE_ID: '' }, + }); + let output = ''; + let settled = false; + const timer = setTimeout(() => finish(null), timeoutMs); + function finish(code: number | null): void { + if (settled) return; + settled = true; + clearTimeout(timer); + child.removeAllListeners(); + child.kill('SIGKILL'); // the TUI runs a render loop until killed + resolve({ code, output }); + } + const collect = (chunk: Buffer): void => { + output += chunk.toString(); + // Resolve as soon as the outcome is observable: the rendered TUI frame + // (construction completed) or the init-error prefix (it crashed). + if (output.includes('Work Items') || /before initialization|Worklog plugin error/.test(output)) { + finish(null); + } + }; + child.stdout.on('data', collect); + child.stderr.on('data', collect); + child.on('exit', (code) => finish(code)); + child.on('error', (err) => { + output += `spawn error: ${String(err)}`; + finish(null); + }); + }); +} + +describe('worklist plugin startup (WL-0MUFRFLRQ004KNDG)', () => { + it( + 'initializes past worker wiring without the modeSwitchWorker TDZ crash', + async () => { + const pluginRoot = fileURLToPath(new URL('..', import.meta.url)); + const { output } = await runPluginStartup(pluginRoot, 30_000); + + // The exact TDZ failure that crashed the plugin at startup. + expect(output).not.toMatch(/Cannot access 'modeSwitchWorker' before initialization/); + expect(output).not.toMatch(/before initialization/); + // Any init failure is surfaced on this prefix; none is allowed. + expect(output).not.toMatch(/Worklog plugin error/); + + // Reaching the TUI proves construction completed past the downtime + // worker (where config() runs synchronously) into the render loop. + expect(output).toContain('Work Items'); + }, + 60_000, + ); +}); From 555e41b6c2c004d8ed52c5fb6f88ecdaef72887a Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 18:21:52 +0100 Subject: [PATCH 10/20] WL-0MUFP30T2003OX1F: fall back off per-slot mode on stale/empty slots; count-based spare capacity MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fixes the live stall where the llama-proxy serves slots:[] + slots_stale:true while reporting valid counts. A1 — stale/empty slots are not per-slot identity: - LlamaStatus gains slots_stale?: boolean; parseLlamaStatus parses it (fail-closed null on a malformed value) and an empty slots array is kept but treated as "no per-slot detail", not "zero free slots". - usablePerSlotSlots() returns null for absent/empty/stale slots, used by evaluateIdle and tick() so per-slot mode is never entered on unusable data and the count-based path (available_slots) is used instead. A2 — conservative count-based spare capacity: - With 0 < N < total and no usable per-slot identity, a held lease no longer blocks dispatch into the proxy-reported spare capacity. ownerLeaseCount() and leaseReserve() reserve one slot per lease only when the owner may be idle (local_active_query !== true), so an idle-but-leased slot counted as available is never dispatched onto. Single-slot and N<=0/N>=total keep the strict fail-closed gate. - tick() mirrors the relaxation in the slotOwned gate so the idle gate and the ownership gate cannot disagree. Tests: AC1 (live payload dispatches), AC2 (multi-slot spare + lease), AC3 (single-slot + lease still refuses), AC4 (slots_stale contract + empty/stale fallback). Verified red before the fix, green after. Docs updated. --- docs/dev/downtime-dispatcher.md | 15 ++ packages/herdr/src/downtime-worker.test.ts | 186 +++++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 176 ++++++++++++++++--- 3 files changed, 355 insertions(+), 22 deletions(-) diff --git a/docs/dev/downtime-dispatcher.md b/docs/dev/downtime-dispatcher.md index 1e314ffee..fcc45bf89 100644 --- a/docs/dev/downtime-dispatcher.md +++ b/docs/dev/downtime-dispatcher.md @@ -746,6 +746,21 @@ an agent on a tool call (wl, bash, tests) left the slot "free", so multiple a slot with a live lease is never considered available for a new pane. A single idle-but-owned slot (count-based path) fails closed via the derived `local_lease_active`. + + **Stale/empty per-slot data (WL-0MUFP30T2003OX1F).** The proxy serves + `slots: []` together with `slots_stale: true` when its fresh `/slots` + query fails: the slot COUNTS come from the last-known cache but the + per-slot detail is unavailable. An empty array is **not** "zero free + slots", so the worker treats stale OR empty `slots` as "no per-slot + identity" and falls back to the count-based path. In that path, with a + multi-slot config (`0 < N < total`) a held lease no longer blocks + dispatch into the proxy-reported spare capacity: the count-based gate + uses `available_slots`, reserving one slot per lease only when the owner + may be idle (`local_active_query !== true` — an active query's slot is + already processing and excluded from the count). A single-slot + (`total_slots = 1`) or `N <= 0` / `N >= total` setup keeps the strict + fail-closed gate. The proxy-side improvement (serve cached per-slot + detail when stale) is tracked separately in `llm-manager`. 3. **Contention feedback (AC6)** — the proxy's LIVE `contention_queue_depth` is parsed; while > 0 the dispatcher backs off with outcome reason `proxy-contention` until the queue drains. The sibling diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index 1219094ee..2e7920b69 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -10939,3 +10939,189 @@ describe('local dispatch-lease TTL + own-pane leases (WL-0MU8809SZ0022VZG)', () } }); }); + +// ── Stale/empty slots fallback + count-based spare capacity ─────────── +// (WL-0MUFP30T2003OX1F) + +describe('stale/empty slots fallback + count-based spare capacity (WL-0MUFP30T2003OX1F)', () => { + function makeRaw(overrides: Record = {}): Record { + return { + llama_server_running: true, + active_query: true, + local_active_query: true, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 1, + total_slots: 3, + slots: [], + slots_stale: true, + local_owner_session_id: ['http://localhost:8080', 'audit-pane-session'], + local_owner_lease_remaining_seconds: 645.5, + contention_queue_depth: 0, + contention_queued_count: 0, + ...overrides, + }; + } + + function makeStaleWorker(opts: { + status: LlamaStatus; + requiredFreeSlots: number; + thresholdMs?: number; + runningPanes: number; + }) { + const cfg = { + enabled: true, + thresholdMs: opts.thresholdMs ?? 0, + requiredFreeSlots: opts.requiredFreeSlots, + model: 'plan', + cwd: '/repo', + noCandidateCooldownMs: 3_600_000, + browseItemCount: 20, + }; + const poller = createDowntimePoller( + 'http://proxy:8000', + vi.fn().mockResolvedValue(jsonResponseFixture(opts.status)), + ); + const deps = makeDeps({ + getNextItem: vi.fn().mockResolvedValue({ + ok: true, + candidate: { id: 'WL-ABC', title: 'Some task', stage: 'intake_complete' }, + }), + getRunningDowntimePanes: vi.fn().mockResolvedValue({ + ok: true, + count: opts.runningPanes, + paneIds: [], + records: [], + }), + }); + const worker = createDowntimeWorker({ poller, deps, config: () => ({ ...cfg }) }); + return { worker, deps }; + } + + it('AC4: parses slots_stale and preserves the empty slots array', () => { + const status = parseLlamaStatus(makeRaw()); + expect(status).not.toBeNull(); + expect(status!.slots).toEqual([]); + expect(status!.slots_stale).toBe(true); + // The array owner form still normalises (child WL-0MU88086A0089US4). + expect(status!.local_owner_session_ids).toEqual(['audit-pane-session']); + expect(status!.local_owner_session_id).toBe('audit-pane-session'); + }); + + it('AC4: a malformed slots_stale fails closed (null)', () => { + expect(parseLlamaStatus(makeRaw({ slots_stale: 'yes' }))).toBeNull(); + expect(parseLlamaStatus(makeRaw({ slots_stale: 1 }))).toBeNull(); + }); + + it('AC4: empty/stale slots are NOT per-slot identity — evaluateIdle falls back to the count', () => { + // Active local query → the leased slot is processing, not reserved → 2 free >= N=2. + const active = parseLlamaStatus(makeRaw({ available_slots: 2 }))!; + expect(evaluateIdle(active, 2)).toBe(true); + // Idle-but-leased (no active query) → reserve the leased slot → 1 < 2. + const idleLease = parseLlamaStatus( + makeRaw({ available_slots: 2, local_active_query: false, active_query: false }), + )!; + expect(evaluateIdle(idleLease, 2)).toBe(false); + }); + + it('AC1: live payload (stale/empty slots, lease, live pane) dispatches into the free slot', async () => { + vi.useFakeTimers(); + try { + // The exact live shape: total=3, available=1, slots:[], slots_stale:true, + // an owner lease held by a dispatched pane. N=1 (single-pane dispatch). + const status: LlamaStatus = { + llama_server_running: true, + active_query: true, + local_active_query: true, + model_switch_in_progress: false, + local_lease_active: true, + available_slots: 1, + total_slots: 3, + slots: [], + slots_stale: true, + local_owner_session_id: 'audit-pane-session', + local_owner_session_ids: ['audit-pane-session'], + local_owner_lease_remaining_seconds: 645.5, + contention_queue_depth: 0, + contention_queued_count: 0, + }; + const { worker, deps } = makeStaleWorker({ + status, + requiredFreeSlots: 1, + thresholdMs: 1_000, + runningPanes: 1, + }); + const start = 1_000_000; + vi.setSystemTime(start); + await worker.tick(); // baseline + vi.setSystemTime(start + 5_000); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(true); + expect(deps.spawnAgentPane).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }); + + it('AC2: count-based multi-slot with spare capacity and a held lease dispatches', async () => { + vi.useFakeTimers(); + try { + // 3 slots, 2 free, N=2, an active local query holding the lease: the RCA + // window shape. The machine-wide lease must not block the spare capacity. + const status: LlamaStatus = { + llama_server_running: true, + active_query: true, + local_active_query: true, + model_switch_in_progress: false, + local_lease_active: true, + available_slots: 2, + total_slots: 3, + local_owner_session_id: 'dispatched-pane-session', + local_owner_session_ids: ['dispatched-pane-session'], + local_owner_lease_remaining_seconds: 840, + contention_queue_depth: 0, + contention_queued_count: 0, + }; + const { worker, deps } = makeStaleWorker({ + status, + requiredFreeSlots: 2, + thresholdMs: 1_000, + runningPanes: 1, + }); + const start = 2_000_000; + vi.setSystemTime(start); + await worker.tick(); + vi.setSystemTime(start + 5_000); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(true); + expect(deps.spawnAgentPane).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }); + + it('AC3: count-based single-slot with a held lease still refuses', async () => { + const status: LlamaStatus = { + llama_server_running: true, + active_query: false, + local_active_query: false, + model_switch_in_progress: false, + local_lease_active: false, + available_slots: 1, + total_slots: 1, + local_owner_session_id: 'operator-session', + local_owner_session_ids: ['operator-session'], + contention_queue_depth: 0, + contention_queued_count: 0, + }; + const { worker, deps } = makeStaleWorker({ + status, + requiredFreeSlots: 1, + runningPanes: 1, + }); + const outcome = await worker.tick(); + expect(outcome.dispatched).toBe(false); + expect(worker.blockReason).toBe('slot-owner'); + expect(deps.spawnAgentPane).not.toHaveBeenCalled(); + }); +}); diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 37358ecef..41b0ca474 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -517,12 +517,23 @@ export interface LlamaStatus { * pre-feature proxies. */ contention_queued_count?: number; + /** + * Proxy degradation flag (LP-0MSVP7XJ6008QPKX, consumed by + * WL-0MUFP30T2003OX1F): `true` when the served slot COUNTS came from the + * proxy's last-known cache because the fresh `/slots` query failed. When + * true the per-slot `slots` detail cannot be trusted/paired with the + * counts, so the worker must fall back to the count-based path. ABSENT on + * pre-feature proxies (treated as not stale). + */ + slots_stale?: boolean; /** * Per-slot identity (LP-0MSG5TA7Y002GN39): served by proxies that expose * slot-level detail. ABSENT on pre-feature proxies — the worker then * falls back to the count-based all-slots-free logic. When present, the * downtime worker tracks idle duration PER SLOT ID so a configured N - * requires the SAME N slots continuously free. + * requires the SAME N slots continuously free. An EMPTY array means "no + * per-slot detail available" (WL-0MUFP30T2003OX1F) — never "zero free + * slots" — and likewise falls back to the count-based path. */ slots?: LlamaSlot[]; } @@ -615,6 +626,90 @@ export function countFreeUnownedSlots(slots: LlamaSlot[]): number { return count; } +/** + * Usable per-slot identity (WL-0MUFP30T2003OX1F): the `slots` array is only + * trustworthy when it is NON-EMPTY and NOT flagged stale by the proxy. An + * empty array (`slots: []`) means "no per-slot detail available" — NOT "zero + * free slots" — and `slots_stale: true` means the counts came from the + * proxy's last-known cache after a failed /slots query, so the detail cannot + * be paired with them. In both cases the worker must fall back to the + * count-based path; `null` is that signal. + */ +function usablePerSlotSlots(status: LlamaStatus): LlamaSlot[] | null { + if (!Array.isArray(status.slots)) return null; + if (status.slots.length === 0) return null; + if (status.slots_stale === true) return null; + return status.slots; +} + +/** + * Number of local dispatch leases the proxy reports (WL-0MUFP30T2003OX1F): + * the normalised `local_owner_session_ids` list when present, else the legacy + * single `local_owner_session_id` string, else 1 when only a positive lease + * TTL is served. Used both for the owner-lease qualifier and to reserve + * possibly-idle leased slots when the worker only has count-based data. + */ +function ownerLeaseCount(status: LlamaStatus): number { + if (Array.isArray(status.local_owner_session_ids)) { + return status.local_owner_session_ids.length; + } + if ( + typeof status.local_owner_session_id === 'string' && + status.local_owner_session_id.length > 0 + ) { + return 1; + } + if ( + typeof status.local_owner_lease_remaining_seconds === 'number' && + Number.isFinite(status.local_owner_lease_remaining_seconds) && + status.local_owner_lease_remaining_seconds > 0 + ) { + return 1; + } + return 0; +} + +/** + * Slots to reserve for a held lease in the count-based path + * (WL-0MUFP30T2003OX1F). While the lease owner is actively generating + * (`local_active_query === true`) its slot is processing and already excluded + * from `available_slots`, so nothing is reserved; otherwise the owner may be + * idle-but-leased, and one slot per lease is reserved so an idle leased slot + * counted as "available" is never dispatched onto. + */ +function leaseReserve(status: LlamaStatus): number { + return status.local_active_query === true ? 0 : ownerLeaseCount(status); +} + +/** + * Genuinely-free slot count for the count-based path + * (WL-0MUFP30T2003OX1F): the proxy's `available_slots` minus any reserved + * lease slots (never negative). + */ +function countBasedFreeSlots(status: LlamaStatus): number { + const available = Number.isFinite(status.available_slots) ? status.available_slots : 0; + return Math.max(0, available - leaseReserve(status)); +} + +/** + * Count-based spare-capacity decision (WL-0MUFP30T2003OX1F): with a + * multi-slot config (0 < N < total) but NO usable per-slot identity, the + * proxy's `available_slots` count is the only availability signal. A held + * local lease must not block dispatch into the spare slots, so this mirrors + * the per-slot spare-capacity relaxation using the count (after reserving + * possibly-idle leased slots). Fail-closed on ambiguous/missing fields. + */ +function countBasedSpareCapacity(status: LlamaStatus, requiredFreeSlots: number): boolean { + const total = status.total_slots; + const available = status.available_slots; + if (!status.llama_server_running) return false; + if (status.model_switch_in_progress) return false; + if (!Number.isFinite(total) || total <= 0) return false; + if (!Number.isFinite(available) || available < 0) return false; + if (requiredFreeSlots <= 0 || requiredFreeSlots >= total) return false; + return countBasedFreeSlots(status) >= requiredFreeSlots; +} + /** * True when the proxy reports an idle state for the required free-slot * count: @@ -659,16 +754,23 @@ export function isIdleStatus(status: LlamaStatus, requiredFreeSlots: number): bo * the global gate is the per-slot-safe subset (server up + no model switch * only) — a query/lease tied to a busy slot is the operator's own session * and must not block dispatch into the free slots (F1 tests AC1/AC2). + * + * Count-based spare-capacity (WL-0MUFP30T2003OX1F): when per-slot identity is + * unusable (stale/empty `slots`) but 0 < N < total AND a local lease is held, + * the same relaxation applies to the proxy's `available_slots` count (after + * reserving possibly-idle leased slots) instead of stalling for the whole + * lease. */ export function evaluateIdle(status: LlamaStatus, requiredFreeSlots: number): boolean { const total = status.total_slots; if (!Number.isFinite(total) || total <= 0) return false; // ambiguous → busy - // Per-slot mode: per-slot identity present AND 0 < N < total. The relaxed - // global gate applies (server up + no model switch); the slot requirement - // is the per-slot free count. + // Per-slot mode: usable per-slot identity present AND 0 < N < total. The + // relaxed global gate applies (server up + no model switch); the slot + // requirement is the per-slot free count. + const perSlotSlots = usablePerSlotSlots(status); if ( - Array.isArray(status.slots) && + perSlotSlots !== null && requiredFreeSlots > 0 && requiredFreeSlots < total ) { @@ -676,10 +778,22 @@ export function evaluateIdle(status: LlamaStatus, requiredFreeSlots: number): bo // Fail-closed counting: an entry without an explicit boolean // `is_processing` is treated as processing (busy), never free. Owned // slots (live lease) are excluded (AC5, WL-0MTYZXSLN008HZOW). - const free = countFreeUnownedSlots(status.slots); + const free = countFreeUnownedSlots(perSlotSlots); return free >= requiredFreeSlots; } + // Count-based spare-capacity (WL-0MUFP30T2003OX1F): multi-slot config with + // 0 < N < total but no usable per-slot identity, and a held lease. The + // strict all-slots-free fallback below would stall for the whole (adaptive) + // lease; the proxy's count says the capacity is real. + if ( + ownerLeaseCount(status) > 0 && + requiredFreeSlots > 0 && + requiredFreeSlots < total + ) { + return countBasedSpareCapacity(status, requiredFreeSlots); + } + const effective = requiredFreeSlots > 0 && requiredFreeSlots < total ? total : requiredFreeSlots; @@ -898,6 +1012,16 @@ export function parseLlamaStatus(raw: unknown): LlamaStatus | null { (typeof leaseSeconds === 'number' && Number.isFinite(leaseSeconds) && leaseSeconds > 0); } + // Optional degradation flag (LP-0MSVP7XJ6008QPKX): absent on pre-feature + // proxies. A malformed (non-boolean) value is ambiguous → null (busy, + // fail-closed), matching the other optional flags. When true the per-slot + // `slots` detail is unusable (WL-0MUFP30T2003OX1F). + let slotsStale: boolean | undefined; + if (o.slots_stale !== undefined) { + if (typeof o.slots_stale !== 'boolean') return null; + slotsStale = o.slots_stale; + } + // Optional per-slot identity (LP-0MSG5TA7Y002GN39): absent on pre-feature // proxies (slots stays undefined — backward compatible). A malformed // array (non-array, entry missing/empty slot_id, non-boolean @@ -989,6 +1113,7 @@ export function parseLlamaStatus(raw: unknown): LlamaStatus | null { contention_queue_depth: contentionQueueDepth, contention_queued_count: contentionQueuedCount, slots, + slots_stale: slotsStale, }; } @@ -5264,14 +5389,15 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // session and must not reset the free slots' timers (spare-capacity // dispatch, parent WL-0MT32F90V008UAD2). A slot reporting processing // resets only its own timer. + const perSlotSlots = usablePerSlotSlots(status); const perSlotMode = - Array.isArray(status.slots) && + perSlotSlots !== null && cfg.requiredFreeSlots > 0 && cfg.requiredFreeSlots < status.total_slots; let idle: boolean; let ready: boolean; - if (perSlotMode && Array.isArray(status.slots)) { + if (perSlotMode && perSlotSlots !== null) { const globalIdle = perSlotGlobalIdleChecks(status); // Display-only: the global idle tracker also reflects per-slot query // activity for the title bar idle indicator — when any slot is @@ -5279,12 +5405,12 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // not "idle". The dispatch logic (spare-capacity relaxation) is // unaffected because free-slot count comes from perSlotTracker, not // tracker.idleSince. (parent WL-0MT65T14L002HTWB) - const anySlotProcessing = status.slots.some( + const anySlotProcessing = perSlotSlots.some( (s) => typeof s.is_processing === 'boolean' && s.is_processing, ); tracker.record(globalIdle && !anySlotProcessing); if (globalIdle) { - perSlotTracker.record(status.slots); + perSlotTracker.record(perSlotSlots); idle = true; ready = perSlotTracker.thresholdMetCount(cfg.thresholdMs) >= cfg.requiredFreeSlots; @@ -5326,10 +5452,13 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // minimums (WL-0MT32F90V008UAD2 AC3): audit needs ≥2 (parent + Phase 2 // child), single-pane tiers need ≥1; idle-duration gate (configured N) // is unchanged and shared. - const freeSlots = - Array.isArray(status.slots) - ? countFreeUnownedSlots(status.slots) - : status.available_slots; + // Count-based: the proxy's own free-slot count (historical behaviour). + // The lease reserve in `countBasedSpareCapacity` is a GATE only — the + // reported budget stays the proxy figure so the strict single-slot path + // and its decision log are unchanged. + const freeSlots = perSlotSlots + ? countFreeUnownedSlots(perSlotSlots) + : status.available_slots; // Mode-aware Phase 2 parallelism inputs (WL-0MT50S9JW001DHME): the // genuine free-slot snapshot (never the total budget), the current @@ -5401,15 +5530,18 @@ export function createDowntimeWorker(opts: DowntimeWorkerConfig): DowntimeWorker // assumption was wrong (WL-0MU8809SZ0022VZG). The per-slot path // (WL-0MU8807BI008C9ME) is what keeps a dispatched pane's own lease // from blocking the OTHER free unowned slots. - const ownerLeaseHeld = - (parseLocalOwnerSessionId(status.local_owner_session_id) !== undefined) || - (typeof status.local_owner_lease_remaining_seconds === 'number' && - Number.isFinite(status.local_owner_lease_remaining_seconds) && - status.local_owner_lease_remaining_seconds > 0); + const ownerLeaseHeld = ownerLeaseCount(status) > 0; + // Count-based spare-capacity (WL-0MUFP30T2003OX1F): when per-slot + // identity is unusable and 0 < N < total, a held lease no longer blocks + // dispatch into the proxy-reported spare slots. This mirrors the + // `evaluateIdle` relaxation exactly, so the idle gate and the ownership + // gate can never disagree. + const countBasedSpare = + !perSlotMode && countBasedSpareCapacity(status, cfg.requiredFreeSlots); const slotOwned = - perSlotMode && Array.isArray(status.slots) - ? countFreeUnownedSlots(status.slots) === 0 - : ownerLeaseHeld && (runningPanes ?? 0) > 0; + perSlotMode && perSlotSlots !== null + ? countFreeUnownedSlots(perSlotSlots) === 0 + : ownerLeaseHeld && (runningPanes ?? 0) > 0 && !countBasedSpare; // LIVE depth only (WL-0MU1DWXO600153OI): `contention_queued_count` is // cumulative telemetry and must never gate dispatch. const contentionQueueDepth = From 635d423448c1eefb6acfd9b5c87855bb244a13fb Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 18:20:27 +0100 Subject: [PATCH 11/20] test(herdr): regression-test needsProducerReview on the live dispatch path (WL-0MU72WJ8C0005GIE) --- docs/dev/downtime-dispatcher.md | 9 ++ packages/herdr/src/downtime-worker.test.ts | 129 ++++++++++++++++++++- 2 files changed, 134 insertions(+), 4 deletions(-) diff --git a/docs/dev/downtime-dispatcher.md b/docs/dev/downtime-dispatcher.md index fcc45bf89..3de255b93 100644 --- a/docs/dev/downtime-dispatcher.md +++ b/docs/dev/downtime-dispatcher.md @@ -428,6 +428,15 @@ leader path equally skips review-gated entries (retaining them for later re-offe flag is cleared). The filter report is "no candidate" (not a `wl-error` strike) and the no-candidate cooldown is not triggered while review-gated work exists. +**Live Herdr-head thread (WL-0MU72WJ8C0005GIE).** The flag reaches +`classifyItemForDispatch` on BOTH dispatch paths. The normal scan in +`dispatchFromHerdrList` builds its `DowntimeItemInfo` field-by-field from the Herdr +head item, so it must thread `needsProducerReview` explicitly; the offer path +(`computeMostImportantItem`) passes the item object directly, so it always honoured +the flag. Before the threading fix (`022f1b24`) the two paths disagreed and the live +path auto-dispatched a `needsProducerReview: true` item — the regression suite +(`needsProducerReview === true blocks a non-critical item…`) pins the agreement. + ### Review-queue depth gate — producer review policy (WL-0MT2UQWOR007CYY9; live-path rewire WL-0MTTSWC1X005P4VD) The **producer review policy**: while the root-only `completed`/`in_review` queue is deep diff --git a/packages/herdr/src/downtime-worker.test.ts b/packages/herdr/src/downtime-worker.test.ts index 2e7920b69..c3b6aa165 100644 --- a/packages/herdr/src/downtime-worker.test.ts +++ b/packages/herdr/src/downtime-worker.test.ts @@ -8841,6 +8841,127 @@ describe('critical-first scan on Herdr-head path (WL-0MU6UL3XY001M3VT)', () => { }); }); +// ── Herdr-head dispatch threads needsProducerReview (WL-0MU72WJ8C0005GIE) ── +// +// The live Herdr-head dispatch path (`dispatchFromHerdrList` → normal scan) +// builds its `classifyItemForDispatch` input from the Herdr item fields. Before +// the fix (022f1b24) it OMITTED `needsProducerReview`, so a non-critical item +// flagged for producer review was dispatched anyway — even though the offer +// path (`computeMostImportantItem`, which passes the item object directly) +// already honoured the flag. These tests pin AC1–AC3: the flag blocks a +// non-critical plan_complete / idea candidate, the direct path agrees with the +// offer path, and clearing the flag restores dispatchability. + +describe('Herdr-head dispatch threads needsProducerReview (WL-0MU72WJ8C0005GIE)', () => { + const implementItem = (id: string, overrides: Partial = {}): DowntimeHerdrItem => ({ + id, + title: `Non-critical ${id}`, + status: 'open', + stage: 'plan_complete', + priority: 'medium', + risk: 'Low', + effort: 'S', + sortIndex: 10, + ...overrides, + }); + + const intakeItem = (id: string, overrides: Partial = {}): DowntimeHerdrItem => ({ + id, + title: `Idea ${id}`, + status: 'open', + stage: 'idea', + priority: 'medium', + sortIndex: 10, + ...overrides, + }); + + const dispatchDeps = (items: DowntimeHerdrItem[]): DowntimeWorkerDeps => makeDeps({ + getHerdrListHead: vi.fn().mockResolvedValue({ ok: true, items }), + claimItem: vi.fn().mockResolvedValue({ ok: true }), + spawnAgentPane: vi.fn().mockResolvedValue({ ok: true }), + recordDispatch: vi.fn().mockResolvedValue(true), + }); + + describe('AC2 — the flag blocks a non-critical candidate on dispatchDowntimeWork', () => { + it('blocks a plan_complete item (implement) and dispatches the next eligible item', async () => { + const deps = dispatchDeps([ + implementItem('NPR-GATED', { needsProducerReview: true, sortIndex: 1 }), + implementItem('NPR-ALLOWED', { needsProducerReview: false, sortIndex: 2 }), + ]); + + const outcome = await dispatchDowntimeWork(deps, { model: 'plan', cwd: '/repo' }); + + expect(outcome.dispatched).toBe(true); + expect(outcome.kind).toBe('implement'); + expect(outcome.candidate?.id).toBe('NPR-ALLOWED'); + // The gated item was never claimed. + expect(deps.claimItem).not.toHaveBeenCalledWith('NPR-GATED', expect.any(Object), '/repo'); + }); + + it('blocks an idea item (intake) and dispatches the next eligible item', async () => { + const deps = dispatchDeps([ + intakeItem('NPR-IDEA-GATED', { needsProducerReview: true, sortIndex: 1 }), + intakeItem('NPR-IDEA-ALLOWED', { needsProducerReview: false, sortIndex: 2 }), + ]); + + const outcome = await dispatchDowntimeWork(deps, { model: 'plan', cwd: '/repo' }); + + expect(outcome.dispatched).toBe(true); + expect(outcome.kind).toBe('intake'); + expect(outcome.candidate?.id).toBe('NPR-IDEA-ALLOWED'); + expect(deps.claimItem).not.toHaveBeenCalledWith('NPR-IDEA-GATED', expect.any(Object), '/repo'); + }); + + it('dispatches nothing when every candidate is review-gated', async () => { + const deps = dispatchDeps([ + implementItem('NPR-ONLY', { needsProducerReview: true }), + ]); + + const outcome = await dispatchDowntimeWork(deps, { model: 'plan', cwd: '/repo' }); + + expect(outcome.dispatched).toBe(false); + expect(deps.claimItem).not.toHaveBeenCalled(); + expect(deps.spawnAgentPane).not.toHaveBeenCalled(); + }); + + it('clearing the flag restores dispatchability (same item shape)', async () => { + const gated = implementItem('NPR-CLEAR', { needsProducerReview: true }); + const blocked = await dispatchDowntimeWork(dispatchDeps([gated]), { model: 'plan', cwd: '/repo' }); + expect(blocked.dispatched).toBe(false); + + gated.needsProducerReview = false; + const released = await dispatchDowntimeWork(dispatchDeps([gated]), { model: 'plan', cwd: '/repo' }); + expect(released.dispatched).toBe(true); + expect(released.candidate?.id).toBe('NPR-CLEAR'); + }); + }); + + describe('AC3 — direct and offer paths agree on the producer-review gate', () => { + it('both the direct dispatch and the offer skip the gated item and pick the same next item', async () => { + const items = [ + implementItem('NPR-PARITY-GATED', { needsProducerReview: true, sortIndex: 1 }), + implementItem('NPR-PARITY-ALLOWED', { needsProducerReview: false, sortIndex: 2 }), + ]; + + const direct = await dispatchDowntimeWork(dispatchDeps(items), { model: 'plan', cwd: '/repo' }); + const offer = await computeMostImportantItem(dispatchDeps(items), '/repo'); + + expect(direct.dispatched).toBe(true); + expect(direct.candidate?.id).toBe('NPR-PARITY-ALLOWED'); + expect(offer).toMatchObject({ ok: true, candidate: { id: 'NPR-PARITY-ALLOWED' } }); + }); + + it('the offer reports no candidate when every candidate is review-gated', async () => { + const offer = await computeMostImportantItem( + dispatchDeps([implementItem('NPR-OFFER-ONLY', { needsProducerReview: true })]), + '/repo', + ); + + expect(offer).toMatchObject({ ok: true, noCandidate: true }); + }); + }); +}); + // ── RCA: duplicate re-dispatch of a critical in-flight item ───────────── // Parent WL-0MUBEZ6PE002WLP4 / F1 WL-0MUBVKPLP006RRDJ (AC1.1). // @@ -9187,10 +9308,10 @@ describe('one dispatch per in-flight critical item (WL-0MUBVKS5I007LSWB / AC5)', // // Blocking is done by CLASSIFICATION SHAPE (a non-dispatchable stage for // open items, out-of-recency for completed/in_review) rather than by the -// `needsProducerReview` flag: on the current `dev` the live Herdr-head -// dispatcher builds its `classifyItemForDispatch` input WITHOUT threading -// `needsProducerReview`, so that flag does not block on this path yet (a -// separate defect tracked as a discovered-from work item). +// `needsProducerReview` flag: the window-extension tests deliberately isolate +// the window mechanism from the review gate. (The flag now blocks on this +// path too — the field is threaded into `classifyItemForDispatch` as of +// WL-0MU72WJ8C0005GIE / 022f1b24.) describe('dispatch-window extension — head-cap starvation (WL-0MU6UL3GQ0015AA5)', () => { const OLD = new Date(Date.now() - 30 * 24 * 60 * 60 * 1000).toISOString(); From ef71b3376738f09133219789b808539048fbf30b Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 18:25:05 +0100 Subject: [PATCH 12/20] WL-0MUFSQMH90086I7W: import PaneLifecycleKind and guard herdr plugin build downtime-worker.ts referenced the PaneLifecycleKind type in the closePane dependency signature without importing it, so npm run build in packages/herdr failed with TS2304 while the root build (which excludes packages/herdr) stayed green. Add the type import and a regression guard test that type-checks the herdr project with tsc --noEmit, so an unimported type can no longer ship unnoticed. --- packages/herdr/src/build-guard.test.ts | 43 ++++++++++++++++++++++++++ packages/herdr/src/downtime-worker.ts | 1 + 2 files changed, 44 insertions(+) create mode 100644 packages/herdr/src/build-guard.test.ts diff --git a/packages/herdr/src/build-guard.test.ts b/packages/herdr/src/build-guard.test.ts new file mode 100644 index 000000000..74ccab34b --- /dev/null +++ b/packages/herdr/src/build-guard.test.ts @@ -0,0 +1,43 @@ +/** + * Build-guard regression test (WL-0MUFSQMH90086I7W). + * + * The herdr plugin is not compiled by the root `tsc` — the root tsconfig + * includes only the repo-root `src/**`, and `packages/herdr` has its own + * build. A missing type import in the plugin therefore shipped to `dev` + * unnoticed: `downtime-worker.ts` referenced the `PaneLifecycleKind` type in + * its `closePane` dependency signature without importing it, so + * `npm run build` inside `packages/herdr` failed with TS2304 while the root + * build stayed green. + * + * This guard compiles the plugin's own tsconfig and asserts it produces no + * diagnostics, so any future type error in `packages/herdr` fails the suite + * instead of reaching `dev`. + */ + +import { describe, it, expect } from 'vitest'; +import { execFileSync } from 'node:child_process'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; + +const packageDir = path.resolve(path.dirname(fileURLToPath(import.meta.url)), '..'); + +describe('herdr plugin build guard', () => { + it('type-checks with tsc --noEmit and reports no errors', () => { + let failed = false; + let diagnostics = ''; + + try { + execFileSync('npx', ['tsc', '--noEmit'], { + cwd: packageDir, + encoding: 'utf8', + stdio: ['ignore', 'pipe', 'pipe'], + }); + } catch (error) { + failed = true; + const e = error as { stdout?: string; stderr?: string }; + diagnostics = `${e.stdout ?? ''}${e.stderr ?? ''}`; + } + + expect(failed, `tsc reported type errors:\n${diagnostics}`).toBe(false); + }, 120_000); +}); diff --git a/packages/herdr/src/downtime-worker.ts b/packages/herdr/src/downtime-worker.ts index 41b0ca474..4aea01702 100644 --- a/packages/herdr/src/downtime-worker.ts +++ b/packages/herdr/src/downtime-worker.ts @@ -149,6 +149,7 @@ import { appendPaneCloseLogEntry as _appendPaneCloseLogEntry, type DispatchMarker, type PaneCloseLogEntry, + type PaneLifecycleKind, } from './downtime-log.js'; import { classifyPaneLifecycle, From 0de733027aba9fe019a614d6ae18f7146a0d80e2 Mon Sep 17 00:00:00 2001 From: pi Date: Thu, 24 Sep 2026 22:55:32 +0100 Subject: [PATCH 13/20] WL-0MU9Z7L8X00117BI: Implementation complete --- packages/tui/extensions/README.md | 34 ++- .../Worklog/lib/recovery/register-recovery.ts | 53 +++- .../lib/recovery/retry-after-header.test.ts | 228 ++++++++++++++++++ .../Worklog/lib/recovery/retry-logic.ts | 114 ++++++++- 4 files changed, 412 insertions(+), 17 deletions(-) create mode 100644 packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts diff --git a/packages/tui/extensions/README.md b/packages/tui/extensions/README.md index c260b2e2b..0289ad2fe 100644 --- a/packages/tui/extensions/README.md +++ b/packages/tui/extensions/README.md @@ -249,9 +249,8 @@ Recovery behaviour is driven by `DEFAULT_RECOVERY_CONFIG` in ### Server-Requested Retry Delays (`Retry-After`) When a provider asks the client to wait — e.g. the llm-proxy startup-ramp gate -returns HTTP `503` with a `Retry-After` header and a body containing -`retry_after` (seconds) — the retry loop honours that hint instead of -retrying on the plain exponential schedule: +returns HTTP `503` with a `Retry-After` header — the retry loop honours that +hint instead of retrying on the plain exponential schedule: - The delay is the **larger** of the exponential backoff and the server-requested delay, so the client never retries sooner than asked @@ -264,11 +263,28 @@ retrying on the plain exponential schedule: (the proxy's `startup_ramp.max_seconds`, default 180s) without surfacing a hard failure. -Supported forms: `retry-after-ms` / `retry_after_ms` (milliseconds), -`retry-after` / `retry_after` delta-seconds (fractional allowed), and -HTTP-date `Retry-After`. Escaped JSON bodies (`\"retry_after\": 9`) are also -parsed. Parsing lives in `parseServerRetryDelayMs()` and the single decision -point `resolveRetryDelay()` in `retry-logic.ts`. +#### Where the hint is read from + +The server hint is resolved from two sources, in precedence order: + +1. **Response headers** (`after_provider_response` / `fetch` capture). Pi's + `openai-completions` provider throws on a non-2xx response *before* the + `after_provider_response` extension event fires, and the resulting + assistant error message drops the header. The recovery module therefore + installs a transparent `globalThis.fetch` wrapper + (`createRetryHintCapturingFetch()`) that records the parsed + `Retry-After` / `Retry-After-Ms` header for 429/5xx responses and clears it + on 2xx. This is the source that works for the llm-proxy startup ramp. +2. **Assistant error message** (`parseServerRetryDelayMs()`), for providers + that fold the hint into the error text (e.g. a JSON body containing + `retry_after`). Real llm-proxy startup-ramp messages do **not** carry this + field — the header is authoritative. + +`resolveRetryDelay()` is the single decision point that combines both sources +and hands the delay to `calculateDelay()`. Supported header/body forms: +`retry-after-ms` / `retry_after_ms` (milliseconds), `retry-after` / +`retry_after` delta-seconds (fractional allowed), and HTTP-date `Retry-After`. +Escaped JSON bodies (`\"retry_after\": 9`) are also parsed. ### `/retry` Command @@ -309,7 +325,7 @@ The recovery module is implemented in `Worklog/lib/recovery/` and consists of: | File | Purpose | |------|---------| | `error-patterns.ts` | Error classification patterns for all 8 categories | -| `retry-logic.ts` | Exponential backoff, `Retry-After`/`retry_after` parsing and jitter, state managers, interruptible sleep | +| `retry-logic.ts` | Exponential backoff, `Retry-After` header/`retry_after` parsing (plus a `fetch` capture wrapper) and jitter, state managers, interruptible sleep | | `recovery.ts` | Compact-and-continue, checkpoint-and-terminate, and single-shot parse-error continue handlers | | `retry-command.ts` | `/retry` command interface (status, reset, manual-trigger) | | `register-recovery.ts` | Extension lifecycle wiring (agent_end, turn_end, session_start, session_compact) | diff --git a/packages/tui/extensions/Worklog/lib/recovery/register-recovery.ts b/packages/tui/extensions/Worklog/lib/recovery/register-recovery.ts index ecd8621ab..a5bbedd08 100644 --- a/packages/tui/extensions/Worklog/lib/recovery/register-recovery.ts +++ b/packages/tui/extensions/Worklog/lib/recovery/register-recovery.ts @@ -32,7 +32,12 @@ import { type RetryCommandContext, type RetryCommandOptions, } from './retry-command.js'; -import { formatDuration, resolveRetryDelay, DEFAULT_BACKOFF_CONFIG } from './retry-logic.js'; +import { + formatDuration, + resolveRetryDelay, + createRetryHintCapturingFetch, + DEFAULT_BACKOFF_CONFIG, +} from './retry-logic.js'; let _recoveryRegistered = false; @@ -49,6 +54,13 @@ let _notifyFn: ((message: string, level: 'info' | 'warning' | 'error') => void) // Timestamp of the last completed triggerInvisibleContinue call. let _lastInvisibleContinueTime = 0; +// Server-requested retry delay captured from the latest provider response +// headers (`Retry-After` / `Retry-After-Ms`). Consumed by the retry loop. +let _lastServerRetryHintMs: number | undefined = undefined; + +// Guards against installing the fetch hint capture more than once. +let _fetchHintCaptureInstalled = false; + /** * Register the recovery module with the extension API. * @@ -65,6 +77,7 @@ export function registerRecoveryModule(pi: ExtensionAPI): void { // the built-in retry from racing with our retry loop. suppressBuiltinRetry(); captureAgentInstance(); + installFetchRetryHintCapture(); // Refresh the notify function on every handler that carries a ctx. pi.on('agent_end', async (_event, ctx) => { @@ -373,14 +386,18 @@ async function triggerInvisibleContinue(): Promise { while (true) { if (interruptibleState.userAborted || interruptibleState.sessionGeneration !== _sessionGenerationAtStart) return; - // Capture the server-requested retry delay (`Retry-After` / - // `retry_after`) from the error message before the error is removed - // from agent state, then honour it (AC1/AC2). + // Capture the server-requested retry delay before the error is removed + // from agent state, then honour it (AC1/AC2). The header captured by + // `installFetchRetryHintCapture()` takes precedence over the + // error-message fallback: real startup_ramp errors carry the hint only + // on the `Retry-After` header, never in the message text. attempt++; const { delayMs: delay, serverHintMs } = resolveRetryDelay( attempt, lastErrorMessageFromAgentState(), DEFAULT_BACKOFF_CONFIG, + Math.random, + _lastServerRetryHintMs, ); // Remove the error assistant message from agent state @@ -582,6 +599,34 @@ function lastMessageIsRetryableError(): boolean { return lastMsg?.role === 'assistant' && lastMsg.stopReason === 'error'; } +// ── Server retry-hint capture (fetch wrapper) ───────────────────────── + +/** + * Capture the server-requested retry delay from provider HTTP response + * headers. + * + * Pi's `openai-completions` provider throws on a non-2xx response before the + * `after_provider_response` extension event fires, and the assistant error + * message does not carry the `Retry-After` header value. Wrapping + * `globalThis.fetch` is the only point at which the recovery module can see + * the header for that provider. The wrapper is transparent: it returns the + * original response untouched and never swallows errors. + */ +function installFetchRetryHintCapture(): void { + if (_fetchHintCaptureInstalled) return; + const originalFetch = globalThis.fetch; + if (typeof originalFetch !== 'function') return; + _fetchHintCaptureInstalled = true; + try { + globalThis.fetch = createRetryHintCapturingFetch(originalFetch, (hintMs) => { + _lastServerRetryHintMs = hintMs; + }); + } catch { + // Non-writable fetch in this runtime — fall back to message parsing. + _fetchHintCaptureInstalled = false; + } +} + // ── Built-in retry suppression ──────────────────────────────────────── /** diff --git a/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts b/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts new file mode 100644 index 000000000..cbcf316aa --- /dev/null +++ b/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts @@ -0,0 +1,228 @@ +/** + * Tests for server-requested retry delays carried on HTTP response headers. + * + * Why this file exists (WL-0MU9Z7L8X00117BI RCA): the original fix parsed the + * retry hint out of the assistant error *message*. Real llm-proxy startup-ramp + * errors do NOT carry `retry_after` in that message — the observed shape is + * + * 503: {"type":"startup_ramp","code":"startup_ramp","message":"Server is starting up; retry shortly."} + * + * — and the machine-readable hint is only on the `Retry-After` response header. + * Pi's `openai-completions` provider throws before the + * `after_provider_response` extension event fires, so the header never reaches + * the extension through events. The recovery module therefore captures the + * header from a transparent `globalThis.fetch` wrapper and feeds it into the + * retry loop. + * + * Run: cd /home/rgardler/projects/ContextHub && npx vitest run packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts + */ + +import { describe, it, expect, vi } from 'vitest'; +import { + calculateDelay, + resolveRetryDelay, + parseServerRetryDelayMs, + parseRetryAfterHeaders, + createRetryHintCapturingFetch, + DEFAULT_BACKOFF_CONFIG, + type BackoffConfig, +} from './retry-logic.js'; + +// The exact error message shape observed in production logs (no retry_after). +const REAL_RAMP_503 = + '503: {"type":"startup_ramp","code":"startup_ramp","message":"Server is starting up; retry shortly."}'; + +// ── parseRetryAfterHeaders: Headers object ──────────────────────────── + +describe('parseRetryAfterHeaders (Headers object)', () => { + it('parses a delta-seconds Retry-After header', () => { + const headers = new Headers({ 'Retry-After': '7' }); + expect(parseRetryAfterHeaders(headers)).toBe(7000); + }); + + it('prefers Retry-After-Ms over Retry-After', () => { + const headers = new Headers({ 'Retry-After-Ms': '5000', 'Retry-After': '9' }); + expect(parseRetryAfterHeaders(headers)).toBe(5000); + }); + + it('parses a fractional delta-seconds header', () => { + expect(parseRetryAfterHeaders(new Headers({ 'Retry-After': '2.5' }))).toBe(2500); + }); + + it('parses a future HTTP-date header', () => { + const future = new Date(Date.now() + 10_000).toUTCString(); + const parsed = parseRetryAfterHeaders(new Headers({ 'Retry-After': future })); + expect(parsed).toBeDefined(); + expect(parsed!).toBeGreaterThan(5000); + expect(parsed!).toBeLessThanOrEqual(10_000); + }); + + it('returns 0 (retry now) for a past HTTP-date header', () => { + const past = new Date(Date.now() - 10_000).toUTCString(); + expect(parseRetryAfterHeaders(new Headers({ 'Retry-After': past }))).toBe(0); + }); + + it('returns undefined when the headers carry no hint', () => { + expect(parseRetryAfterHeaders(new Headers({ 'Content-Type': 'application/json' }))).toBeUndefined(); + }); + + it('returns undefined for malformed values', () => { + expect(parseRetryAfterHeaders(new Headers({ 'Retry-After': 'soon' }))).toBeUndefined(); + }); +}); + +// ── parseRetryAfterHeaders: plain record ────────────────────────────── + +describe('parseRetryAfterHeaders (plain record)', () => { + it('matches header names case-insensitively', () => { + expect(parseRetryAfterHeaders({ 'RETRY-AFTER': '12' })).toBe(12000); + expect(parseRetryAfterHeaders({ 'rEtRy-AfTeR': '3' })).toBe(3000); + }); + + it('is tolerant of absent / null input', () => { + expect(parseRetryAfterHeaders(undefined)).toBeUndefined(); + expect(parseRetryAfterHeaders(null)).toBeUndefined(); + expect(parseRetryAfterHeaders({})).toBeUndefined(); + }); + + it('returns undefined for negative values', () => { + expect(parseRetryAfterHeaders({ 'retry-after': '-3' })).toBeUndefined(); + }); +}); + +// ── resolveRetryDelay: header hint takes precedence ─────────────────── + +describe('resolveRetryDelay with a header hint', () => { + const noJitter = () => 0; + + it('honours a header hint that exceeds the exponential backoff', () => { + const result = resolveRetryDelay(1, undefined, DEFAULT_BACKOFF_CONFIG, noJitter, 7000); + expect(result.serverHintMs).toBe(7000); + expect(result.hintSource).toBe('header'); + expect(result.delayMs).toBe(7000); + }); + + it('prefers the header hint over a message hint', () => { + const result = resolveRetryDelay(1, '503: {"retry_after": 3}', DEFAULT_BACKOFF_CONFIG, noJitter, 9000); + expect(result.hintSource).toBe('header'); + expect(result.delayMs).toBe(9000); + }); + + it('falls back to the message hint when no header hint is present', () => { + const result = resolveRetryDelay(1, '503: {"retry_after": 3}', DEFAULT_BACKOFF_CONFIG, noJitter, undefined); + expect(result.hintSource).toBe('message'); + expect(result.delayMs).toBe(3000); + }); + + it('caps a large header hint at the configured maximum', () => { + const result = resolveRetryDelay(1, undefined, DEFAULT_BACKOFF_CONFIG, noJitter, 90_000); + expect(result.delayMs).toBe(60_000); + }); + + it('treats a negative/NaN header hint as absent', () => { + expect(resolveRetryDelay(1, undefined, DEFAULT_BACKOFF_CONFIG, noJitter, -1).hintSource).toBeUndefined(); + expect(resolveRetryDelay(1, undefined, DEFAULT_BACKOFF_CONFIG, noJitter, Number.NaN).hintSource).toBeUndefined(); + }); + + it('applies upward-only jitter to a header-derived delay', () => { + const config: BackoffConfig = { baseDelayMs: 2000, maxDelayMs: 60000, multiplier: 2, serverHintJitterRatio: 0.25 }; + expect(calculateDelay(1, config, 8000, () => 0.5)).toBe(9000); + expect(calculateDelay(1, config, 8000, () => 0.5)).toBeGreaterThanOrEqual(8000); + }); +}); + +// ── createRetryHintCapturingFetch ───────────────────────────────────── + +function makeResponse(status: number, headers: Record = {}): Response { + return new Response('body', { status, headers }); +} + +describe('createRetryHintCapturingFetch', () => { + it('captures the hint from a 503 response', async () => { + const onHint = vi.fn(); + const capture = createRetryHintCapturingFetch( + async () => makeResponse(503, { 'Retry-After': '11' }), + onHint, + ); + await capture('http://example.test'); + expect(onHint).toHaveBeenCalledWith(11_000); + }); + + it('captures the hint from a 429 response', async () => { + const onHint = vi.fn(); + const capture = createRetryHintCapturingFetch( + async () => makeResponse(429, { 'Retry-After-Ms': '2500' }), + onHint, + ); + await capture('http://example.test'); + expect(onHint).toHaveBeenCalledWith(2500); + }); + + it('clears the hint on a successful response', async () => { + const onHint = vi.fn(); + const capture = createRetryHintCapturingFetch(async () => makeResponse(200), onHint); + await capture('http://example.test'); + expect(onHint).toHaveBeenCalledWith(undefined); + }); + + it('reports undefined for a retryable response without a hint', async () => { + const onHint = vi.fn(); + const capture = createRetryHintCapturingFetch(async () => makeResponse(502), onHint); + await capture('http://example.test'); + expect(onHint).toHaveBeenCalledWith(undefined); + }); + + it('returns the original response untouched', async () => { + const response = makeResponse(503, { 'Retry-After': '5' }); + const capture = createRetryHintCapturingFetch(async () => response, () => {}); + await expect(capture('http://example.test')).resolves.toBe(response); + }); + + it('propagates fetch rejections (network errors) without capturing', async () => { + const onHint = vi.fn(); + const capture = createRetryHintCapturingFetch(async () => { + throw new Error('network down'); + }, onHint); + await expect(capture('http://example.test')).rejects.toThrow('network down'); + expect(onHint).not.toHaveBeenCalled(); + }); + + it('does not clear the hint on a non-2xx, non-retryable response', async () => { + const onHint = vi.fn(); + const capture = createRetryHintCapturingFetch(async () => makeResponse(400), onHint); + await capture('http://example.test'); + expect(onHint).not.toHaveBeenCalled(); + }); +}); + +// ── RCA regression: the real error shape + header hint ──────────────── + +describe('startup_ramp RCA regression', () => { + it('the real error message carries no parseable hint', () => { + expect(parseServerRetryDelayMs(REAL_RAMP_503)).toBeUndefined(); + }); + + it('honours the Retry-After header that the message dropped', () => { + const headerHint = parseRetryAfterHeaders(new Headers({ 'Retry-After': '12' })); + const result = resolveRetryDelay(1, REAL_RAMP_503, DEFAULT_BACKOFF_CONFIG, () => 0, headerHint); + expect(headerHint).toBe(12_000); + expect(result.hintSource).toBe('header'); + expect(result.delayMs).toBe(12_000); + }); + + it('does not retry sooner than the hint across a full startup ramp', () => { + const config: BackoffConfig = { baseDelayMs: 2000, maxDelayMs: 60000, multiplier: 2, serverHintJitterRatio: 0.25 }; + let elapsed = 0; + let attempt = 0; + while (elapsed < 180_000 && attempt < 100) { + attempt++; + // Proxy degrades hints across the ramp, 5s .. 18s. + const headerHint = parseRetryAfterHeaders(new Headers({ 'Retry-After': String(5 + (attempt % 14)) })); + const { delayMs } = resolveRetryDelay(attempt, REAL_RAMP_503, config, () => 0, headerHint); + expect(delayMs).toBeGreaterThanOrEqual(headerHint!); + elapsed += delayMs; + } + expect(elapsed).toBeGreaterThanOrEqual(180_000); + expect(attempt).toBeLessThan(100); + }); +}); diff --git a/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts b/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts index 379eefa36..ce0622d99 100644 --- a/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts +++ b/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts @@ -113,6 +113,97 @@ function normaliseDelayMs(value: number, factor: number): number | undefined { return Math.round(ms); } +/** + * Parse a server-requested retry delay from HTTP response headers. + * + * The llm-proxy startup-ramp gate sets a `Retry-After` header (delta-seconds + * or HTTP-date) on its 503 response. Pi's `openai-completions` provider throws + * before the `after_provider_response` extension event fires and formats the + * assistant error message without the header value, so the recovery retry + * loop captures the header from a `fetch` wrapper and parses it here. + * + * Supports both a real `Headers` object (case-insensitive by construction) and + * a plain string record. `retry-after-ms` wins over `retry-after`, matching the + * provider-level retry helper's precedence. + * + * @param headers - Response headers (`Headers` or a plain record) + * @returns Delay in milliseconds, or `undefined` when absent or malformed + */ +export function parseRetryAfterHeaders( + headers: Headers | Record | undefined | null, +): number | undefined { + if (!headers) return undefined; + + const get = (name: string): string | undefined => { + const maybeHeaders = headers as Headers; + if (typeof maybeHeaders.get === 'function') { + const value = maybeHeaders.get(name); + return value === null ? undefined : value; + } + const record = headers as Record; + const direct = record[name]; + if (typeof direct === 'string') return direct; + for (const [key, value] of Object.entries(record)) { + if (key.toLowerCase() === name && typeof value === 'string') return value; + } + return undefined; + }; + + // 1. Milliseconds form (checked first so `retry-after-ms` is not read as + // delta-seconds). + const msHeader = get('retry-after-ms'); + if (msHeader !== undefined) { + const value = Number.parseFloat(msHeader); + if (Number.isFinite(value)) return normaliseDelayMs(value, 1); + } + + // 2. Delta-seconds form, then HTTP-date form. + const retryAfter = get('retry-after'); + if (retryAfter !== undefined) { + const seconds = Number.parseFloat(retryAfter); + if (Number.isFinite(seconds)) return normaliseDelayMs(seconds, 1000); + const target = Date.parse(retryAfter); + if (!Number.isNaN(target)) { + // A past date means "retry now" (0ms) rather than an invalid hint. + return Math.max(0, Math.round(target - Date.now())); + } + } + + return undefined; +} + +/** + * Wrap a `fetch` implementation so retryable provider responses report the + * server-requested retry delay (`Retry-After` / `Retry-After-Ms` on 429/5xx) + * to `onHint`. Successful (2xx) responses report `undefined` so a stale hint + * is not reused. The response is returned untouched and fetch rejections + * propagate unchanged. + * + * This is the transport-level source of the retry hint for providers that + * throw before an extension event can observe the response headers. + * + * @param originalFetch - The fetch implementation to delegate to + * @param onHint - Called with the parsed delay in ms (or undefined to clear) + * @returns A drop-in fetch wrapper + */ +export function createRetryHintCapturingFetch( + originalFetch: typeof fetch, + onHint: (hintMs: number | undefined) => void, +): typeof fetch { + const capturingFetch = async (input: RequestInfo | URL, init?: RequestInit): Promise => { + const response = await originalFetch(input, init); + if (response && typeof response.status === 'number') { + if (response.status === 429 || response.status >= 500) { + onHint(parseRetryAfterHeaders(response.headers)); + } else if (response.status >= 200 && response.status < 300) { + onHint(undefined); + } + } + return response; + }; + return capturingFetch as typeof fetch; +} + /** * Calculate delay for a given attempt number. * @@ -168,17 +259,32 @@ export function calculateDelay( * @param errorMessage - The assistant error message * @param config - Backoff configuration (defaults if not provided) * @param random - Random source in [0, 1) used for jitter (injectable for tests) - * @returns The delay in milliseconds and the parsed server hint, if present + * @param headerHintMs - Retry delay parsed from the response `Retry-After` + * header (see {@link parseRetryAfterHeaders}); takes precedence over the + * error-message hint + * @returns The delay in milliseconds, the parsed server hint (if any), and + * which source produced it */ export function resolveRetryDelay( attempt: number, errorMessage: string | undefined | null, config: BackoffConfig = DEFAULT_BACKOFF_CONFIG, random: () => number = Math.random, -): { delayMs: number; serverHintMs?: number } { - const serverHintMs = parseServerRetryDelayMs(errorMessage); + headerHintMs?: number, +): { delayMs: number; serverHintMs?: number; hintSource?: 'header' | 'message' } { + const headerHint = + typeof headerHintMs === 'number' && Number.isFinite(headerHintMs) && headerHintMs >= 0 + ? headerHintMs + : undefined; + const messageHint = parseServerRetryDelayMs(errorMessage); + const serverHintMs = headerHint ?? messageHint; + const hintSource = headerHint !== undefined ? 'header' : messageHint !== undefined ? 'message' : undefined; const delayMs = calculateDelay(attempt, config, serverHintMs, random); - return serverHintMs === undefined ? { delayMs } : { delayMs, serverHintMs }; + + const result: { delayMs: number; serverHintMs?: number; hintSource?: 'header' | 'message' } = { delayMs }; + if (serverHintMs !== undefined) result.serverHintMs = serverHintMs; + if (hintSource !== undefined) result.hintSource = hintSource; + return result; } /** From bf3f83de945197acf8ff11c6976e32ddb5e5e140 Mon Sep 17 00:00:00 2001 From: pi Date: Fri, 25 Sep 2026 06:05:31 +0100 Subject: [PATCH 14/20] fix(WL-0MSLW8GHQ0092PJK): remove id from error message valid-fields list The error messages for --fields invalid-field errors were listing 'id' among valid fields, but id is always included in output regardless of request. Users should not need to request it. Fixes: - packages/shared/src/fields.ts: filter 'id' from VALID_FIELDS in error - src/commands/list.ts: same for list command error - src/commands/search.ts: same for search command error - packages/shared/src/fields.test.ts: add test verifying id is excluded - tests/cli/fields-integration.test.ts: update test expectations Bug reported by manual audit: 'Remove id from the help text provided when invalid fields are detected.' --- packages/shared/src/fields.test.ts | 16 ++++++++++++++++ packages/shared/src/fields.ts | 5 ++++- src/commands/list.ts | 5 ++++- src/commands/search.ts | 5 ++++- tests/cli/fields-integration.test.ts | 8 ++++++-- 5 files changed, 34 insertions(+), 5 deletions(-) diff --git a/packages/shared/src/fields.test.ts b/packages/shared/src/fields.test.ts index fac2b8ccc..ad5533030 100644 --- a/packages/shared/src/fields.test.ts +++ b/packages/shared/src/fields.test.ts @@ -146,4 +146,20 @@ describe('pickFields', () => { it('VALID_FIELDS has no unexpected entries', () => { expect(VALID_FIELDS).toHaveLength(14); }); + + it('error message for unknown fields excludes id from valid fields list', () => { + let error: Error | undefined; + try { + pickFields(SAMPLE_ITEM, ['bogusField']); + } catch (e) { + error = e instanceof Error ? e : undefined; + } + expect(error).toBeDefined(); + // id is always included regardless of request, so it must NOT appear in + // the error message's valid-fields list. + expect(error!.message).not.toMatch(/Valid fields:.*\bid\b/); + // but other fields should still appear + expect(error!.message).toContain('title'); + expect(error!.message).toContain('status'); + }); }); diff --git a/packages/shared/src/fields.ts b/packages/shared/src/fields.ts index a7b6019a3..c1b4a5439 100644 --- a/packages/shared/src/fields.ts +++ b/packages/shared/src/fields.ts @@ -65,7 +65,10 @@ export function pickFields( // Validate: reject unknown field names. const unknown = fields.filter((f) => !VALID_FIELDS.includes(f as (typeof VALID_FIELDS)[number])); if (unknown.length > 0) { - const validList = VALID_FIELDS.join(', '); + // id is always included regardless of request, so omit it from the + // error message's valid-fields list — the caller doesn't need to + // request it. + const validList = VALID_FIELDS.filter(f => f !== 'id').join(', '); throw new Error( `Unknown fields: ${unknown.join(', ')}. Valid fields: ${validList}` ); diff --git a/src/commands/list.ts b/src/commands/list.ts index 062bb922b..44a9c18b4 100644 --- a/src/commands/list.ts +++ b/src/commands/list.ts @@ -45,7 +45,10 @@ export default function register(ctx: PluginContext): void { requestedFields = options.fields.split(',').map(f => f.trim()).filter(Boolean); const unknown = requestedFields.filter(f => !VALID_FIELDS.includes(f as (typeof VALID_FIELDS)[number])); if (unknown.length > 0) { - const fieldsError = `Unknown fields: ${unknown.join(', ')}. Valid fields: ${VALID_FIELDS.join(', ')}`; + // id is always included regardless of request, so omit it from the + // valid-fields list shown in the error message. + const validFieldsList = VALID_FIELDS.filter(f => f !== 'id').join(', '); + const fieldsError = `Unknown fields: ${unknown.join(', ')}. Valid fields: ${validFieldsList}`; output.error(fieldsError, { success: false, error: fieldsError, message: fieldsError }); process.exit(1); } diff --git a/src/commands/search.ts b/src/commands/search.ts index 3e21cb5aa..6ff7a1b95 100644 --- a/src/commands/search.ts +++ b/src/commands/search.ts @@ -119,7 +119,10 @@ export default function register(ctx: PluginContext): void { requestedFields = options.fields.split(',').map(f => f.trim()).filter(Boolean); const unknown = requestedFields.filter(f => !VALID_FIELDS.includes(f as (typeof VALID_FIELDS)[number])); if (unknown.length > 0) { - const fieldsError = `Unknown fields: ${unknown.join(', ')}. Valid fields: ${VALID_FIELDS.join(', ')}`; + // id is always included regardless of request, so omit it from the + // valid-fields list shown in the error message. + const validFieldsList = VALID_FIELDS.filter(f => f !== 'id').join(', '); + const fieldsError = `Unknown fields: ${unknown.join(', ')}. Valid fields: ${validFieldsList}`; output.error(fieldsError, { success: false, error: fieldsError, message: fieldsError }); process.exit(1); } diff --git a/tests/cli/fields-integration.test.ts b/tests/cli/fields-integration.test.ts index 9bd3ff67c..0d9395d04 100644 --- a/tests/cli/fields-integration.test.ts +++ b/tests/cli/fields-integration.test.ts @@ -45,10 +45,14 @@ describe('--fields end-to-end integration', () => { expect(searchErr).not.toBeNull(); // Both commands report the same valid-field vocabulary. expect(listErr![1]).toBe(searchErr![1]); - // The vocabulary contains the documented field set. - for (const f of ['id', 'title', 'description', 'status', 'stage', 'priority', 'issueType', 'assignee', 'tags', 'createdAt', 'updatedAt', 'parentId', 'needsProducerReview', 'sortIndex']) { + // The vocabulary lists all fields EXCEPT id (id is always included, + // so it is not mentioned in the error message). + const expectedFields = ['title', 'description', 'status', 'stage', 'priority', 'issueType', 'assignee', 'tags', 'createdAt', 'updatedAt', 'parentId', 'needsProducerReview', 'sortIndex']; + for (const f of expectedFields) { expect(listErr![1]).toContain(f); } + // id must NOT appear in the valid-fields list + expect(listErr![1]).not.toMatch(/\bid\b/); }); it('search --fields combined with --semantic keeps projection and search metadata', async () => { From 41e46e6d031ed092d70777bc897e22ae0b0fc700 Mon Sep 17 00:00:00 2001 From: pi Date: Fri, 25 Sep 2026 10:14:24 +0100 Subject: [PATCH 15/20] fix(WL-0MSLW8GHQ0092PJK): accept space-separated --fields values Users naturally write `--fields id, title` with a space after the comma. The shell splits that into separate argv tokens, so Commander assigned only "id," to --fields and treated the following tokens as positional arguments (the trailing one silently dropped as an excess argument). The projection then appeared to return only the first requested field. normalizeFieldsArgv() merges the continuation tokens back into the --fields value when (and only when) the accumulated value ends with a comma, so a complete --fields list followed by a positional search/query term is left untouched. Applied before Commander parses argv in src/cli.ts and mirrored in the in-process test harness. The -f shorthand is shared with --file on export/import/migrate/sync/doctor, so it is only treated as --fields for list/search. Tests: unit tests for normalizeFieldsArgv; integration tests for the space-separated form on both wl list and wl search, including a positional query after a complete --fields value. --- src/cli-utils.ts | 66 ++++++++++++++++++++++ src/cli.ts | 11 +++- tests/cli/cli-inproc.ts | 9 ++- tests/cli/list-fields.test.ts | 32 +++++++++++ tests/cli/search-fields.test.ts | 26 +++++++++ tests/unit/cli-args.test.ts | 99 +++++++++++++++++++++++++++++++++ 6 files changed, 239 insertions(+), 4 deletions(-) create mode 100644 tests/unit/cli-args.test.ts diff --git a/src/cli-utils.ts b/src/cli-utils.ts index 5703ff2a9..6ec239f3f 100644 --- a/src/cli-utils.ts +++ b/src/cli-utils.ts @@ -14,6 +14,72 @@ const _cliUtilsRequire = createRequire(import.meta.url); import { WORKLOG_VERSION } from './version.js'; +/** + * Normalise space-separated `--fields` values before Commander parses argv. + * + * Users naturally write a comma-separated list with spaces, e.g. + * `wl list --fields id, title, status`. The shell tokenises that as + * `["--fields", "id,", "title,", "status"]`, so Commander assigns only + * `"id,"` to `--fields` and treats the remaining tokens as positional + * arguments (the trailing `status` is silently dropped as an excess + * argument). The projection then appears to ignore most of the requested + * fields. + * + * When (and only when) the accumulated `--fields` value ends with a comma — + * the unambiguous signal that more fields follow — the following non-option + * tokens are merged back into the value. A value that does not end with a + * comma is left untouched, so a legitimate positional search/query term + * after `--fields id,title` is preserved. + * + * @param argv - argument list without the leading node/script entries + * @returns a new argument list with `--fields` continuations merged + */ +export function normalizeFieldsArgv(argv: readonly string[]): string[] { + const out: string[] = []; + + // `--fields` is unique to list/search, but the `-f` shorthand is shared + // with `--file` on export/import/migrate/sync/doctor. Only treat `-f` as + // `--fields` when the invocation targets a command that defines it. + const shortFlagIsFields = argv.includes('list') || argv.includes('search'); + + for (let i = 0; i < argv.length; i++) { + const token = argv[i]; + + if (token === '--fields' || (token === '-f' && shortFlagIsFields)) { + out.push(token); + if (i + 1 < argv.length) { + let value = argv[++i]; + while ( + value.trim().endsWith(',') && + i + 1 < argv.length && + !argv[i + 1].startsWith('-') + ) { + value += argv[++i]; + } + out.push(value); + } + continue; + } + + if (token.startsWith('--fields=')) { + let value = token; + while ( + value.trim().endsWith(',') && + i + 1 < argv.length && + !argv[i + 1].startsWith('-') + ) { + value += argv[++i]; + } + out.push(value); + continue; + } + + out.push(token); + } + + return out; +} + /** * Output formatting helpers */ diff --git a/src/cli.ts b/src/cli.ts index afe257bf3..7c02f07ff 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -4,7 +4,7 @@ */ import { Command } from 'commander'; -import { createPluginContext, getVersion } from './cli-utils.js'; +import { createPluginContext, getVersion, normalizeFieldsArgv } from './cli-utils.js'; import { loadPlugins } from './plugin-loader.js'; import { renderCliMarkdown, resolveMarkdownEnabled } from './cli-output.js'; import { loadConfig } from './config.js'; @@ -176,6 +176,15 @@ if (_parsedWatch.enabled) { process.exit(0); } +// Merge space-separated --fields continuations (e.g. `--fields id, title`) +// before Commander parses argv. Without this, the trailing token is mistaken +// for the positional search/query argument and the projection silently drops +// requested fields (WL-0MSLW8GHQ0092PJK). +process.argv = [ + ...process.argv.slice(0, 2), + ...normalizeFieldsArgv(process.argv.slice(2)), +]; + // Allowed formats for validation const ALLOWED_FORMATS = new Set(['concise', 'summary', 'normal', 'full', 'raw', 'markdown', 'text', 'plain', 'auto']); diff --git a/tests/cli/cli-inproc.ts b/tests/cli/cli-inproc.ts index 203e89420..d5550ae6e 100644 --- a/tests/cli/cli-inproc.ts +++ b/tests/cli/cli-inproc.ts @@ -1,5 +1,5 @@ import { Command } from 'commander'; -import { createPluginContext } from '../../src/cli-utils.js'; +import { createPluginContext, normalizeFieldsArgv } from '../../src/cli-utils.js'; import { applyWorklogDirOverrideFromArgv, setWorklogDirOverride } from '../../src/worklog-paths.js'; // Import the shared throttler so the in-process harness can wait for any // scheduled GitHub tasks to drain when a parse timeout occurs. Accessing the @@ -98,6 +98,9 @@ export async function runInProcess(commandLine: string, timeoutMs: number = 1500 // find index of the script path (ends with src/cli.ts) const cliIndex = tokens.findIndex(t => t.endsWith(path.join('src', 'cli.ts')) || t.endsWith(path.join('dist', 'cli.js'))); const args = cliIndex >= 0 ? tokens.slice(cliIndex + 1) : tokens; + // Mirror src/cli.ts: merge space-separated --fields continuations before + // Commander parses them (WL-0MSLW8GHQ0092PJK). + const normalizedArgs = normalizeFieldsArgv(args); // Capture stdout/stderr const out: string[] = []; @@ -110,7 +113,7 @@ export async function runInProcess(commandLine: string, timeoutMs: number = 1500 const origConsoleWarn = console.warn; const origConsoleInfo = console.info; const origArgv = process.argv; - const argv = ['node', 'worklog', ...args]; + const argv = ['node', 'worklog', ...normalizedArgs]; process.argv = argv; process.stdout.write = ((chunk: any, enc?: any, cb?: any) => { try { @@ -144,7 +147,7 @@ export async function runInProcess(commandLine: string, timeoutMs: number = 1500 // Mirror src/cli.ts: apply --worklog-dir from argv BEFORE creating the // plugin context so ctx.dataPath (and -f/--file defaults) reflect the // override (WL-0MSAH26DD001XXST). - applyWorklogDirOverrideFromArgv(args); + applyWorklogDirOverrideFromArgv(normalizedArgs); try { const program = new Command(); diff --git a/tests/cli/list-fields.test.ts b/tests/cli/list-fields.test.ts index 4570fd9fa..9ca9a3aaa 100644 --- a/tests/cli/list-fields.test.ts +++ b/tests/cli/list-fields.test.ts @@ -116,6 +116,38 @@ describe('wl list --fields', () => { expect(Object.keys(wi)).toEqual(['id', 'title']); }); + it('accepts space-separated fields (shell splits --fields id, title)', async () => { + seedWorkItems(state.tempDir, [FULL_ITEM]); + + const { stdout } = await execAsync(`tsx ${cliPath} list --fields id, title --json`); + const result = JSON.parse(stdout); + expect(result.workItems).toHaveLength(1); + const wi = result.workItems[0]; + expect(wi.id).toBe('TEST-1'); + expect(wi.title).toBe('Feature item'); + expect(Object.keys(wi)).toEqual(['id', 'title']); + }); + + it('accepts three or more space-separated fields', async () => { + seedWorkItems(state.tempDir, [FULL_ITEM]); + + const { stdout } = await execAsync(`tsx ${cliPath} list --fields id, title, status --json`); + const result = JSON.parse(stdout); + const wi = result.workItems[0]; + expect(Object.keys(wi)).toEqual(['id', 'title', 'status']); + expect(wi.status).toBe('in-progress'); + }); + + it('does not swallow a positional search term after a complete --fields value', async () => { + seedWorkItems(state.tempDir, [FULL_ITEM]); + + // `--fields id,title` is complete, so `Feature` is a search term, not a field. + const { stdout } = await execAsync(`tsx ${cliPath} list Feature --fields id,title --json`); + const result = JSON.parse(stdout); + expect(result.workItems).toHaveLength(1); + expect(Object.keys(result.workItems[0])).toEqual(['id', 'title']); + }); + it('produces smaller output than full records (projection reduces size)', async () => { const items = Array.from({ length: 50 }, (_, i) => ({ id: `TEST-${i + 1}`, diff --git a/tests/cli/search-fields.test.ts b/tests/cli/search-fields.test.ts index f4d5e61cb..29e4632de 100644 --- a/tests/cli/search-fields.test.ts +++ b/tests/cli/search-fields.test.ts @@ -82,6 +82,32 @@ describe('wl search --fields', () => { expect(errOut).toContain('description'); }); + it('accepts space-separated fields (shell splits --fields id, title)', async () => { + await createItem('Spaced fields item', 'Unique phrase quokka appears here'); + + const { stdout } = await execAsync(`tsx ${cliPath} search quokka --fields id, title --json`); + const result = JSON.parse(stdout); + expect(result.workItems.length).toBeGreaterThan(0); + const wi = result.workItems[0]; + expect(wi.id).toBeDefined(); + expect(wi.title).toBe('Spaced fields item'); + expect('priority' in wi).toBe(false); + // Search metadata is still present alongside the projection + expect('score' in wi).toBe(true); + expect('snippet' in wi).toBe(true); + }); + + it('does not swallow the query when --fields precedes it with space-separated values', async () => { + await createItem('Query after fields item', 'Unique phrase narwhal appears here'); + + const { stdout } = await execAsync(`tsx ${cliPath} search --fields id, title narwhal --json`); + const result = JSON.parse(stdout); + expect(result.workItems.length).toBeGreaterThan(0); + const wi = result.workItems[0]; + expect(wi.id).toBeDefined(); + expect(wi.title).toBe('Query after fields item'); + }); + it('output is unchanged without --fields (backward compatible)', async () => { await createItem('Plain searchable item', 'Unique phrase tiger appears here', ['-p', 'medium']); diff --git a/tests/unit/cli-args.test.ts b/tests/unit/cli-args.test.ts new file mode 100644 index 000000000..56a90881f --- /dev/null +++ b/tests/unit/cli-args.test.ts @@ -0,0 +1,99 @@ +/** + * Unit tests for normalizeFieldsArgv (WL-0MSLW8GHQ0092PJK). + * + * Users write `--fields id, title` with a space after the comma; the shell + * splits that into separate argv tokens. normalizeFieldsArgv merges the + * continuation tokens back into the --fields value when (and only when) the + * accumulated value ends with a comma, so the projection does not silently + * drop requested fields or mistake them for a positional search/query term. + */ + +import { describe, it, expect } from 'vitest'; +import { normalizeFieldsArgv } from '../../src/cli-utils.js'; + +describe('normalizeFieldsArgv', () => { + it('leaves argv without --fields unchanged', () => { + const argv = ['list', '--json', '--stage', 'in_review']; + expect(normalizeFieldsArgv(argv)).toEqual(argv); + }); + + it('merges a two-field space-separated value', () => { + expect(normalizeFieldsArgv(['list', '--fields', 'id,', 'title', '--json'])).toEqual([ + 'list', + '--fields', + 'id,title', + '--json', + ]); + }); + + it('merges three or more space-separated fields', () => { + expect( + normalizeFieldsArgv(['list', '--fields', 'id,', 'title,', 'status', '--json']) + ).toEqual(['list', '--fields', 'id,title,status', '--json']); + }); + + it('merges the -f shorthand', () => { + expect(normalizeFieldsArgv(['list', '-f', 'id,', 'title'])).toEqual([ + 'list', + '-f', + 'id,title', + ]); + }); + + it('does not consume a positional search term when the value does not end with a comma', () => { + // `--fields id,title` is complete; `searchterm` is a positional argument. + expect(normalizeFieldsArgv(['list', '--fields', 'id,title', 'searchterm'])).toEqual([ + 'list', + '--fields', + 'id,title', + 'searchterm', + ]); + }); + + it('preserves a positional argument that precedes --fields', () => { + expect(normalizeFieldsArgv(['list', 'searchterm', '--fields', 'id,', 'title'])).toEqual([ + 'list', + 'searchterm', + '--fields', + 'id,title', + ]); + }); + + it('does not consume an option token as a field continuation', () => { + expect(normalizeFieldsArgv(['list', '--fields', 'id,', '--json', 'title'])).toEqual([ + 'list', + '--fields', + 'id,', + '--json', + 'title', + ]); + }); + + it('merges the --fields= form', () => { + expect(normalizeFieldsArgv(['list', '--fields=id,', 'title', '--json'])).toEqual([ + 'list', + '--fields=id,title', + '--json', + ]); + }); + + it('handles a trailing --fields with no value', () => { + expect(normalizeFieldsArgv(['list', '--fields'])).toEqual(['list', '--fields']); + }); + + it('does not treat -f as --fields for commands where -f means --file', () => { + // `wl export -f ` uses -f for --file; a comma must not merge the + // following positional into the path. + const argv = ['export', '-f', 'data,', 'backup', '--json']; + expect(normalizeFieldsArgv(argv)).toEqual(argv); + }); + + it('leaves a quoted (single-token) value untouched', () => { + expect(normalizeFieldsArgv(['list', '--fields', 'id, title', '--json'])).toEqual([ + 'list', + '--fields', + 'id, title', + '--json', + ]); + }); +}); From e1bea036c04d852901dcf98afccd420b5959e34d Mon Sep 17 00:00:00 2001 From: pi Date: Fri, 25 Sep 2026 18:33:19 +0100 Subject: [PATCH 16/20] WL-0MU9Z7L8X00117BI: Implementation complete --- packages/tui/extensions/README.md | 8 ++++--- .../lib/recovery/retry-after-header.test.ts | 9 ++++++++ .../Worklog/lib/recovery/retry-after.test.ts | 21 ++++++++++++++----- .../Worklog/lib/recovery/retry-logic.ts | 21 +++++++++++++------ 4 files changed, 45 insertions(+), 14 deletions(-) diff --git a/packages/tui/extensions/README.md b/packages/tui/extensions/README.md index 0289ad2fe..e815f1b4d 100644 --- a/packages/tui/extensions/README.md +++ b/packages/tui/extensions/README.md @@ -252,9 +252,11 @@ When a provider asks the client to wait — e.g. the llm-proxy startup-ramp gate returns HTTP `503` with a `Retry-After` header — the retry loop honours that hint instead of retrying on the plain exponential schedule: -- The delay is the **larger** of the exponential backoff and the - server-requested delay, so the client never retries sooner than asked - (bounded by `maxDelayMs`, default 60s). +- When a hint is present it is **authoritative**: the delay tracks the + server-requested delay (plus upward-only jitter, bounded by `maxDelayMs`, + default 60s). The local exponential backoff is used only when the hint is + absent or malformed, so a grown local backoff can never override the + server's recommended wait. - Upward-only jitter (25% by default, `serverHintJitterRatio`) is applied to hint-derived delays so concurrent clients do not retry in lockstep. - Missing or malformed hints fall back to the existing exponential backoff, diff --git a/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts b/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts index cbcf316aa..2e475cd33 100644 --- a/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts +++ b/packages/tui/extensions/Worklog/lib/recovery/retry-after-header.test.ts @@ -119,6 +119,14 @@ describe('resolveRetryDelay with a header hint', () => { expect(result.delayMs).toBe(60_000); }); + it('does not let a grown local backoff override the header hint', () => { + // attempt 6 local exponential is capped at 60000ms, but the header hint is + // authoritative — the local backoff must not override the server's wait. + const result = resolveRetryDelay(6, REAL_RAMP_503, DEFAULT_BACKOFF_CONFIG, noJitter, 8000); + expect(result.hintSource).toBe('header'); + expect(result.delayMs).toBe(8000); + }); + it('treats a negative/NaN header hint as absent', () => { expect(resolveRetryDelay(1, undefined, DEFAULT_BACKOFF_CONFIG, noJitter, -1).hintSource).toBeUndefined(); expect(resolveRetryDelay(1, undefined, DEFAULT_BACKOFF_CONFIG, noJitter, Number.NaN).hintSource).toBeUndefined(); @@ -220,6 +228,7 @@ describe('startup_ramp RCA regression', () => { const headerHint = parseRetryAfterHeaders(new Headers({ 'Retry-After': String(5 + (attempt % 14)) })); const { delayMs } = resolveRetryDelay(attempt, REAL_RAMP_503, config, () => 0, headerHint); expect(delayMs).toBeGreaterThanOrEqual(headerHint!); + expect(delayMs).toBeLessThanOrEqual(config.maxDelayMs); elapsed += delayMs; } expect(elapsed).toBeGreaterThanOrEqual(180_000); diff --git a/packages/tui/extensions/Worklog/lib/recovery/retry-after.test.ts b/packages/tui/extensions/Worklog/lib/recovery/retry-after.test.ts index e5a09b231..c8da9e163 100644 --- a/packages/tui/extensions/Worklog/lib/recovery/retry-after.test.ts +++ b/packages/tui/extensions/Worklog/lib/recovery/retry-after.test.ts @@ -120,9 +120,12 @@ describe('calculateDelay with a server hint', () => { expect(calculateDelay(1, DEFAULT_BACKOFF_CONFIG, 7000, noJitter)).toBe(7000); }); - it('uses the exponential backoff when it exceeds the hint', () => { - // attempt 5 exponential = 32000ms, hint = 5000ms -> floor is 32000ms. - expect(calculateDelay(5, DEFAULT_BACKOFF_CONFIG, 5000, noJitter)).toBe(32000); + it('honours the server hint even when the local exponential has grown larger', () => { + // attempt 5 exponential = 32000ms, hint = 5000ms. The server hint is + // authoritative: the local backoff must not override the recommended wait + // (producer rejection: "the local retry mechanism overriding the + // recommended wait duration"). + expect(calculateDelay(5, DEFAULT_BACKOFF_CONFIG, 5000, noJitter)).toBe(5000); }); it('caps the server-requested delay at the configured maximum', () => { @@ -137,12 +140,20 @@ describe('calculateDelay with a server hint', () => { multiplier: 2, serverHintJitterRatio: 0.25, }; - const floor = 8000; // max(exponential 2000, hint 8000) - expect(calculateDelay(1, config, 8000, () => 0)).toBe(floor); + // Hint-derived delays track the hint, not the (smaller) exponential. + expect(calculateDelay(1, config, 8000, () => 0)).toBe(8000); expect(calculateDelay(1, config, 8000, () => 0.5)).toBe(9000); expect(calculateDelay(1, config, 8000, () => 1)).toBe(10_000); }); + it('does not let the local backoff escalate a hint-derived delay across attempts', () => { + // A constant 7s hint must yield ~7s on every attempt, even at attempt 6 + // where the local exponential would otherwise be capped at 60s. + for (const attempt of [1, 2, 3, 4, 5, 6, 10]) { + expect(calculateDelay(attempt, DEFAULT_BACKOFF_CONFIG, 7000, () => 0)).toBe(7000); + } + }); + it('never retries sooner than the hint under maximum jitter', () => { const config: BackoffConfig = { baseDelayMs: 2000, diff --git a/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts b/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts index ce0622d99..7843b2bf7 100644 --- a/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts +++ b/packages/tui/extensions/Worklog/lib/recovery/retry-logic.ts @@ -211,10 +211,17 @@ export function createRetryHintCapturingFetch( * capped at `maxDelayMs` (existing exponential backoff, unchanged). * * With a usable server hint (from `Retry-After` / `retry_after`): the delay - * is the larger of the exponential backoff and the server-requested delay, - * plus upward-only jitter, capped at `maxDelayMs`. This guarantees the client - * never retries sooner than the server asked (unless the configured cap is - * below the hint). + * tracks the server-requested delay (plus upward-only jitter, capped at + * `maxDelayMs`). The local exponential backoff is **not** combined into this + * value — a growing local backoff must not silently override the server's + * recommendation. + * + * @remarks + * The server hint is authoritative when present. An earlier revision used + * `max(exponential, serverHintMs)`, which let the local exponential override + * the hint once it outgrew it (e.g. `Retry-After: 7` -> retry at 32s/60s). + * That is the behaviour the producer rejected as "the local retry mechanism + * overriding the recommended wait duration". * * @param attempt - The attempt number (1-based) * @param config - Backoff configuration (defaults if not provided) @@ -241,9 +248,11 @@ export function calculateDelay( return exponential; } - const floor = Math.max(exponential, serverHintMs); + // A usable server hint is authoritative: the delay tracks the hint, not the + // local exponential. Upward-only jitter keeps the delay at or above the + // requested wait, and the configurable maximum still bounds it. const jitterRatio = Math.max(0, config.serverHintJitterRatio ?? DEFAULT_SERVER_HINT_JITTER_RATIO); - const jittered = floor * (1 + jitterRatio * random()); + const jittered = serverHintMs * (1 + jitterRatio * random()); return Math.min(Math.round(jittered), config.maxDelayMs); } From 7470e5dc9be71af652e96f348266ebd2e807ed70 Mon Sep 17 00:00:00 2001 From: pi Date: Fri, 25 Sep 2026 20:11:18 +0100 Subject: [PATCH 17/20] WL-0MT1KJNGA006EEHU: Add memwatch memory pressure monitoring and alerting --- docs/dev/memory-monitoring.md | 293 +++++++++++++++++++++++++++ scripts/install-memwatch.sh | 149 ++++++++++++++ scripts/memwatch.sh | 213 +++++++++++++++++++ tests/memwatch.test.ts | 370 ++++++++++++++++++++++++++++++++++ 4 files changed, 1025 insertions(+) create mode 100644 docs/dev/memory-monitoring.md create mode 100755 scripts/install-memwatch.sh create mode 100755 scripts/memwatch.sh create mode 100644 tests/memwatch.test.ts diff --git a/docs/dev/memory-monitoring.md b/docs/dev/memory-monitoring.md new file mode 100644 index 000000000..f9228c18b --- /dev/null +++ b/docs/dev/memory-monitoring.md @@ -0,0 +1,293 @@ +# Memory Pressure Monitoring & Alerting + +**Work Item:** WL-0MT1KJNGA006EEHU — Set up memory pressure monitoring and alerting +**Date:** 2026-09-25 +**Status:** Installed and verified + +--- + +## 1. Summary + +| Component | Mechanism | Status | +|-----------|-----------|--------| +| Live memory pressure check | `scripts/memwatch.sh` via `/etc/cron.d/memwatch` (every minute) | ✅ Installed | +| Alert delivery | journald via `logger -p user.warning` (prefix `MEMWATCH:`) | ✅ Verified | +| Historical memory trend data | sysstat `sar -r` (10-minute interval, 7-day retention) | ✅ Active | +| Log-noise control | State-file deduplication (one alert per level change) | ✅ Verified | + +**Why:** During the 2026-08-20 system hang, the kernel logged *"Under memory +pressure, flushing caches"* 10+ times between 13:27 and 13:40 with no alert and +no early warning. The system had run for 21 days with accumulating memory +pressure and no monitoring to catch it before it became unresponsive. + +**What is monitored:** `/proc/meminfo` `MemAvailable` — the kernel's own estimate +of how much memory is available for new applications without swapping. This is +the standard metric for headroom (it accounts for reclaimable page cache, unlike +`MemFree`). + +--- + +## 2. Monitoring script — `scripts/memwatch.sh` + +The script reads `MemAvailable` (and `MemTotal`) from `/proc/meminfo`, compares +the result against two configurable thresholds, and writes a structured alert to +journald when the pressure level changes. + +### 2.1 Levels + +| Level | Condition (default) | Exit code | Meaning | +|-------|--------------------|-----------|---------| +| `OK` | `MemAvailable` ≥ 4096 MB | 0 | Normal headroom | +| `WARN` | 2048 MB ≤ `MemAvailable` < 4096 MB | 1 | Memory pressure building — investigate | +| `CRIT` | `MemAvailable` < 2048 MB | 2 | Imminent exhaustion — intervene now | +| `ERR` | `MemAvailable` unreadable | 2 | Monitoring failure — check `/proc/meminfo` access | + +Thresholds are absolute MB values (not percentages) so behaviour is predictable +regardless of total RAM. The defaults correspond to ~17% (warning) and ~8% +(critical) of a 24 GB system. + +### 2.2 Log-line format + +One line per level change, written to journald through `logger`: + +``` +MEMWATCH: 2026-09-25 19:00:01 available=3072MB / total=30970MB (9%) level=WARN +``` + +The line contains the timestamp, the available memory value, the total RAM, the +percentage, and the threshold status — satisfying the AC requirement for a +single structured line per interval. + +### 2.3 Deduplication (log-noise control) + +The script records the last reported level in `MEMWATCH_STATE_FILE` (default +`/run/memwatch-state`). A line is emitted **only when the level changes** from the +previous interval: + +``` +OK → WARN → one line (WARN) +WARN → WARN → no line (deduplicated) +WARN → CRIT → one line (CRIT) +CRIT → CRIT → no line (deduplicated) +CRIT → OK → one line (OK) +``` + +This means sustained pressure produces exactly one alert, not one per minute, +bounding log volume even through a long incident. The exit code still reflects +the current level on every run, so external callers can always poll status. + +### 2.4 Configuration + +All settings are file-level variables at the top of the script, each overridable +by an environment variable: + +| Variable | Default | Purpose | +|----------|---------|---------| +| `MEMWATCH_WARNING_MB` | `4096` | Warning threshold (MB) | +| `MEMWATCH_CRITICAL_MB` | `2048` | Critical threshold (MB) | +| `MEMWATCH_MEMINFO` | `/proc/meminfo` | MemAvailable source (tests override this) | +| `MEMWATCH_STATE_FILE` | `/run/memwatch-state` | Deduplication state file | +| `MEMWATCH_LOG_PREFIX` | `MEMWATCH` | Log line prefix | +| `MEMWATCH_LOGGER` | `logger -p user.warning` | Alert delivery command | +| `MEMWATCH_DRY_RUN` | *(unset)* | Log to stdout instead of journald | +| `MEMWATCH_JSON` | *(unset)* | Emit machine-readable JSON | + +### 2.5 Manual use + +```bash +# Production (logs to journald) +scripts/memwatch.sh + +# Dry run — print the alert line to stdout instead of journald +scripts/memwatch.sh --dry-run + +# Machine-readable output +scripts/memwatch.sh --json + +# Custom thresholds +MEMWATCH_WARNING_MB=8192 MEMWATCH_CRITICAL_MB=4096 scripts/memwatch.sh --dry-run +``` + +--- + +## 3. Installation + +`scripts/install-memwatch.sh` deploys the cron job (requires root): + +```bash +sudo scripts/install-memwatch.sh +# Custom thresholds: +sudo scripts/install-memwatch.sh --warning 8192 --critical 4096 +# Preview without installing: +scripts/install-memwatch.sh --dry-run +# Remove it again: +sudo scripts/install-memwatch.sh --uninstall +``` + +Installation has two parts: + +1. The script is **copied to a root-owned location** `/usr/local/sbin/memwatch` + (`root:root`, mode `0755`). This is deliberate: the cron job runs as root, + so the executed script must not be writable by a non-root user — pointing + root cron at a script inside a user-writable checkout would be a + privilege-escalation vector. +2. `/etc/cron.d/memwatch` is written (`root:root`, mode `0644`): + +``` +SHELL=/bin/bash +PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin + +* * * * * root /usr/local/sbin/memwatch +``` + +Only root can modify either file, so a non-root process cannot alter what the +root cron job executes. + +> **Updating the script:** after changing `scripts/memwatch.sh` in the repo, +> re-run `sudo scripts/install-memwatch.sh` to refresh the installed copy. +> The repo is the source of truth; the installed copy is a deploy artefact. + +--- + +## 4. Querying alerts + +```bash +# Recent memory alerts (logger -t MEMWATCH sets the syslog tag) +journalctl -t MEMWATCH --since '1 hour ago' + +# All warning-or-worse entries carrying the MEMWATCH message prefix +journalctl -p warning --since today | grep MEMWATCH + +# Follow live +journalctl -f -t MEMWATCH +``` + +--- + +## 5. Historical trend analysis (sysstat) + +sysstat is active and collecting memory statistics every 10 minutes. The +`sysstat-collect.timer` drives collection; `sysstat-rotate.timer` rotates daily +and `sysstat-summary.timer` builds daily summaries. + +### 5.1 Verified configuration (2026-09-25) + +``` +$ dpkg -l sysstat | tail -1 +ii sysstat 12.7.7-0ubuntu2 amd64 system performance tools for Linux + +$ systemctl status sysstat-collect.timer +● sysstat-collect.timer - Run system activity accounting tool every 10 minutes + Loaded: loaded (/usr/lib/systemd/system/sysstat-collect.timer; enabled) + Active: active (waiting) + +$ grep HISTORY /etc/sysstat/sysstat +HISTORY=7 + +$ ls /var/log/sysstat/ +sa17 sa18 sa19 sa20 sa21 sa22 sa23 sa24 sa25 ... +``` + +- **Collection interval:** 10 minutes (`sysstat-collect.timer`) +- **Raw retention:** 7 days (`HISTORY=7`) +- **Data location:** `/var/log/sysstat/` (daily files `sa
`) + +### 5.2 Example query — memory trends + +```bash +# Today's memory usage, 10-minute samples +sar -r + +# Specific date (day-of-month form) +sar -r -f /var/log/sysstat/sa24 + +# Time-windowed (13:00–14:00 on the 20th — the 2026-08-20 incident) +sar -r -f /var/log/sysstat/sa20 -s 13:00:00 -e 14:00:00 + +# Percentage-used only, sorted to spot peak pressure +sar -r | awk 'NR>3 {print $4, $5}' | sort -k2 -n | tail -20 +``` + +`kbavail` in `sar -r` output is the same `MemAvailable` metric memwatch alerts on, +so the historical data and live alerts are directly comparable. + +### 5.3 Retention extension + +If 7 days is insufficient for long-term trend analysis, raise `HISTORY` in +`/etc/sysstat/sysstat` (e.g. `HISTORY=30`) and reload sysstat. Disk cost is +roughly 1 MB per day per host for the memory-relevant data. + +--- + +## 6. Verification (operator runbook) + +```bash +# 1. Script works against current system state (no journald write) +scripts/memwatch.sh --dry-run + +# 2. Cron file is installed +cat /etc/cron.d/memwatch + +# 3. End-to-end alert emission (writes one real journald line) +logger -p user.warning "MEMWATCH: $(date '+%Y-%m-%d %H:%M:%S') available=0MB level=SELFTEST" +journalctl -t MEMWATCH --since '1 minute ago' | tail -1 + +# 4. Confirm the cron job has run (a MEMWATCH line per level change) +journalctl -t MEMWATCH --since '5 minutes ago' | tail -5 + +# 5. Historical data is queryable +sar -r | tail -5 + +# 6. Automated tests +npx vitest run tests/memwatch.test.ts +``` + +Expected: step 3 prints the `SELFTEST` line; step 4 shows real `level=OK` lines; +step 6 reports 22 passing tests. + +--- + +## 7. False-positive and limitation notes + +- **`MemAvailable` notionally excludes swap pressure.** A system can be swapping + heavily while `MemAvailable` still looks acceptable. Swap monitoring and PSI + (`/proc/pressure/memory`) are **out of scope** for this work item and are + candidates for follow-up work. +- **Warning threshold is intentionally conservative** (4 GB on a 30 GB host). + Sustained `WARN` without `CRIT` indicates memory is being consumed by + reclaimable cache/workloads that the kernel can recover — useful early signal, + not necessarily an emergency. +- **The state file (`/run/memwatch-state`) is cleared on reboot.** After a reboot the first + interval always emits one line (level change from unknown), which is desirable: + it records the post-reboot memory state. +- **Cron granularity is one minute.** The system can exhaust memory faster than + that; memwatch is an early-warning system, not a hard OOM guard. `systemd-oomd` + or `earlyoom` would be the reactive counterpart (out of scope). + +--- + +## 8. Tests + +`tests/memwatch.test.ts` (22 tests) runs the real script with a fixture +`/proc/meminfo` supplied through `MEMWATCH_MEMINFO` and captures output via +`--dry-run`. It covers: + +- OK/WARN/CRIT level classification and exact threshold boundaries +- Per-level deduplication (repeated intervals produce no second line) +- Level-transition logging (OK→WARN, WARN→CRIT, CRIT→OK) +- Configurable thresholds and log prefix +- Unreadable-meminfo error handling (exit 2, `level=ERR`) +- JSON output shape and `--help` + +--- + +## 9. References + +- `/etc/cron.d/memwatch` — installed cron job (this work item) +- `scripts/memwatch.sh` — monitoring script +- `scripts/install-memwatch.sh` — installer +- `tests/memwatch.test.ts` — automated tests +- `/proc/meminfo`, `/proc/pressure/memory` — kernel memory signals +- `/etc/sysstat/sysstat`, `/var/log/sysstat/` — sysstat configuration and data +- `docs/dev/crash-reporting.md` — related host-health monitoring precedent +- `docs/dev/wl-process-spawning-investigation.md` — `wl-process-healthcheck.sh` precedent diff --git a/scripts/install-memwatch.sh b/scripts/install-memwatch.sh new file mode 100755 index 000000000..23542ac2f --- /dev/null +++ b/scripts/install-memwatch.sh @@ -0,0 +1,149 @@ +#!/usr/bin/env bash +# install-memwatch.sh — deploy memwatch memory monitoring as a cron job +# +# Installs the monitoring script to a root-owned location (default +# /usr/local/sbin/memwatch) and writes /etc/cron.d/memwatch to invoke it +# every minute as root. +# +# Copying the script to a root-owned path is deliberate: the cron job runs as +# root, so the executed script must not be modifiable by a non-root user. A +# cron job pointing at a script inside a user-writable checkout would be a +# privilege-escalation vector. +# +# Usage: +# sudo scripts/install-memwatch.sh # defaults +# sudo scripts/install-memwatch.sh --warning 8192 --critical 4096 +# scripts/install-memwatch.sh --dry-run # preview only +# sudo scripts/install-memwatch.sh --uninstall +# +# Environment overrides: +# MEMWATCH_SCRIPT_PATH Source script (default: /memwatch.sh) +# MEMWATCH_INSTALL_PATH Root-owned target (default: /usr/local/sbin/memwatch) +# MEMWATCH_STATE_FILE State file for dedup (default: /run/memwatch-state) +# +# Work Item: WL-0MT1KJNGA006EEHU +# Date: 2026-09-25 + +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "$0")" && pwd)" +MEMWATCH_SCRIPT="${MEMWATCH_SCRIPT_PATH:-$SCRIPT_DIR/memwatch.sh}" +INSTALL_PATH="${MEMWATCH_INSTALL_PATH:-/usr/local/sbin/memwatch}" +CRON_FILE="/etc/cron.d/memwatch" +DRY_RUN=0 +UNINSTALL=0 +WARNING_MB="" +CRITICAL_MB="" + +while [[ $# -gt 0 ]]; do + case "$1" in + --dry-run) DRY_RUN=1; shift ;; + --uninstall) UNINSTALL=1; shift ;; + --warning) WARNING_MB="$2"; shift 2 ;; + --critical) CRITICAL_MB="$2"; shift 2 ;; + -h|--help) + cat <<'EOF' +Usage: install-memwatch.sh [--dry-run] [--uninstall] [--warning MB] [--critical MB] + +Install (or remove) memwatch memory monitoring as a root cron job. + +Options: + --dry-run Show what would be installed without making changes + --uninstall Remove the cron job and installed script + --warning MB Warning threshold in MB (default: script default, 4096) + --critical MB Critical threshold in MB (default: script default, 2048) + -h, --help Show this help +EOF + exit 0 + ;; + *) echo "Unknown option: $1" >&2; exit 1 ;; + esac +done + +if (( DRY_RUN == 0 )) && (( EUID != 0 )); then + echo "Error: this script must be run as root (or via sudo)" >&2 + exit 1 +fi + +MEMWATCH_SCRIPT_ABS="$(cd "$(dirname "$MEMWATCH_SCRIPT")" && pwd)/$(basename "$MEMWATCH_SCRIPT")" + +if (( UNINSTALL )); then + echo "Removing memwatch..." + rm -f "$CRON_FILE" + rm -f "$INSTALL_PATH" + echo "✓ Removed $CRON_FILE and $INSTALL_PATH" + exit 0 +fi + +if [[ ! -f "$MEMWATCH_SCRIPT" ]]; then + echo "Error: memwatch.sh not found at $MEMWATCH_SCRIPT" >&2 + exit 1 +fi + +# Build the optional threshold overrides for the cron line. When unset, the +# script's own defaults (documented at the top of memwatch.sh) apply. +THRESHOLD_ENV="" +if [[ -n "$WARNING_MB" ]]; then + THRESHOLD_ENV+="MEMWATCH_WARNING_MB=$WARNING_MB " +fi +if [[ -n "$CRITICAL_MB" ]]; then + THRESHOLD_ENV+="MEMWATCH_CRITICAL_MB=$CRITICAL_MB " +fi + +CRON_CONTENT="# memwatch - memory pressure monitoring and alerting +# Installed by scripts/install-memwatch.sh (Work Item: WL-0MT1KJNGA006EEHU) +# +# Checks /proc/meminfo MemAvailable every minute and logs a MEMWATCH: line to +# journald when the pressure level changes. See docs/dev/memory-monitoring.md. + +SHELL=/bin/bash +PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin + +* * * * * root ${THRESHOLD_ENV}${INSTALL_PATH} +" + +echo "=== memwatch installer ===" +echo "Source: $MEMWATCH_SCRIPT_ABS" +echo "Install: $INSTALL_PATH (root:root 0755)" +echo "Cron: $CRON_FILE" +echo "Warning: ${WARNING_MB:-