fix(health): a deferred sweep must not erase the last real measurement (#355 follow-up)

docs/deployed-diagnostics.md

@@ -69,11 +69,14 @@ logic of its own by design: the boundary lives in one place, in this repo, with
     "inFlightMs": 4560000,          // this pass has run 76 minutes
     "missedPasses": 76,
     "lastErrorClass": "TimeoutError",
-    // The last COMPLETED sweep's arithmetic (#355). Absent until one completes.
+    // The last ENUMERATING sweep's arithmetic (#355). Absent until one enumerates.
     "candidates": 7,                // work units it pulled and evaluated
     "dispatched": 0,                // work units it dispatched
     "skipped": 7,                   // work units it saw and declined
-    "skipReasons": { "dispatch-terminal": 7 }
+    "skipReasons": { "dispatch-terminal": 7 },
+    // When THOSE counts were measured. Not lastCompletedAtMs, which also
+    // advances on a deferred pass that enumerated nothing.
+    "lastEnumeratedAtMs": 1787224535802
   },
   "eventListener": { "state": "subscribed" },
   "fleetControlPlane": { "state": "closed", "consecutiveFailures": 0, "failureThreshold": 3 }
@@ -99,29 +102,61 @@ logic of its own by design: the boundary lives in one place, in this repo, with
   - `candidates > 0` — the sweep **saw** those issues and **rejected** them. The bug is in eligibility
     evaluation, and `skipReasons` names which gate.
   - `candidates == 0` — the sweep **never pulled** them. The bug is upstream, in discovery/ingestion.
-  - **the three fields absent entirely** — this daemon has not *completed* a sweep (or predates #355).
-    That is not a zero, and must not be read as one: it says nothing about either half. Check
-    `lastCompletedAtMs` and `inFlightMs`.
-
-  They describe the last sweep that settled **successfully**, the same tense as `lastDurationMs`;
-  `lastCompletedAtMs` dates them. A pass that failed leaves them untouched rather than zeroing them.
-
-- **`discoveryDeferred: "sweep-in-flight"`** — the sweep returned immediately because another process
-  held the discovery lease, so it enumerated nothing. Without this, that pass is indistinguishable
-  from one that queried the provider and legitimately found no ready work: both publish
-  `candidates: 0`.
+  - **the three fields absent entirely** — this daemon has not completed a sweep that **enumerated**
+    (or predates #355). That is not a zero, and must not be read as one: it says nothing about either
+    half. Check `discoveryDeferred` first, then `lastCompletedAtMs`, `lastFailureAtMs`, and `inFlightMs`
+    to distinguish a completed deferral, a failure, work still running, and a pre-counter daemon.
+
+  They describe the last sweep that settled successfully **and enumerated**. A pass that failed —
+  or that deferred — leaves them untouched rather than zeroing them.
+
+- **`lastEnumeratedAtMs`** — when those counts were measured, and the field to check before acting on
+  them. It is **not** `lastCompletedAtMs`: that one advances on every settled pass including a
+  deferred one, so on a daemon contending for the discovery lease the counts would otherwise sit
+  beside an ever-fresh completion stamp with no way to tell a measurement one interval old from one
+  four days old. Equal to `lastCompletedAtMs` on a daemon sweeping normally; where they differ, the
+  gap is exactly how stale the counts are.
+
+- **`discoveryDeferred: "sweep-in-flight"`** — the **most recent** pass returned immediately because
+  another process held the discovery lease, so it enumerated nothing. It is tracked apart from the
+  three counts, which describe the last sweep that actually enumerated:
+
+  - **with the counts** — those numbers are from an *earlier* pass, not the one `lastCompletedAtMs`
+    dates. A deferred pass records only this marker; its zeroes measure nothing and must not
+    overwrite a real sweep's numbers, which under a persistently-held lease would erase them.
+  - **alone, with no counts** — nothing has enumerated successfully yet on this daemon. The most
+    recent pass deferred because another process held the lease; an earlier startup attempt may
+    instead have failed before it could publish an outcome.
+
+  `lastCompletedAtMs` *does* move for a deferred pass. That is deliberate: the stall derivation above
+  reads it against `lastStartedAtMs`, so freezing it would report a daemon that is correctly
+  deferring to another owner as hung after ten intervals.
 
 - **`skipReasons`** — `skipped` split by a closed vocabulary
   (`FACTORY_SWEEP_SKIP_REASON_CODES`); zero-count codes are omitted, so an absent key is a zero, and
-  the counts always sum to `skipped`. `dispatch-terminal` and `dispatch-retry-limit` are the two that
-  never clear on their own — a work unit in either needs a human. `dispatch-backoff`,
-  `already-tracked` and `queued-or-escalated` resolve by themselves. `out-of-scope` and `not-ready`
-  mean the gate is working as configured and the issue does not match it — check the deployed
-  `safety` config against the issue rather than the daemon.
+  the counts always sum to `skipped`. The full vocabulary, grouped by what to do about it:
+
+  | code | |
+  |---|---|
+  | `dispatch-terminal`, `dispatch-retry-limit` | **needs a human** — permanently declined, never clears on its own |
+  | `dispatch-backoff`, `dispatch-in-flight`, `already-tracked`, `queued-or-escalated` | transient; resolves by itself |
+  | `out-of-scope`, `not-ready`, `not-dispatchable` | the gate is working as configured and the issue does not match it — check the deployed `safety` config against the issue, not the daemon |
+  | `parked-dependency`, `dependency-cycle` | parked on other work; a cycle needs a human to break it |
+  | `read-failed`, `dispatch-failed` | per-item failures the sweep **absorbed and continued past** (#292/#297) — see below |
+  | `other` | a code this reader's vocabulary does not know, from a producer on another version |
+
+  `read-failed` and `dispatch-failed` count work units an otherwise-**successful** pass gave up on
+  individually. Do **not** reach for `lastErrorClass` to explain them: that field describes a pass
+  that *failed as a whole*, and the success path clears it, so it is absent in exactly this scenario.
+  The per-item messages go to the container log (`[factory] relayfile shed a ready-issue read…`,
+  `[factory] skipped a work unit whose dispatch failed…`); the count here is what tells you to go
+  looking. A rising `read-failed` alongside `state: healthy` is the #297 shedding signature.
 
   Counts only, by construction: issue keys, paths and titles carry customer project and repository
   names and never cross onto this surface. The keys are rebuilt from the reader's own copy of the
-  vocabulary, so a record from another version cannot publish an arbitrary string as one.
+  vocabulary — anything unrecognised is counted under `other` rather than dropped, so the parts keep
+  summing to `skipped` — which is also why a record from another version cannot publish an arbitrary
+  string as a key.
 
 - **`fleetControlPlane`** — an `open` circuit fails every spawn and resume fast, so it gates dispatch
   as hard as a failing sweep. `closed` is the healthy value.

src/cli/diagnose.test.ts

@@ -1,5 +1,6 @@
 import { describe, expect, it } from 'vitest'
 
+import { formatSweepOutcome } from './diagnose'
 import { runFleetCli } from './fleet'
 
 const BASE = 'https://factory.example.com'
@@ -65,6 +66,57 @@ const healthy = {
   },
 }
 
+describe('formatSweepOutcome (#359)', () => {
+  it('attributes a count-free deferral only to the latest pass', () => {
+    const outcome = formatSweepOutcome({
+      state: 'healthy',
+      consecutiveFailures: 0,
+      failureThreshold: 3,
+      discoveryDeferred: 'sweep-in-flight',
+    })
+
+    expect(outcome).toBe(
+      'nothing has enumerated successfully yet — the most recent pass deferred ' +
+      'to another process holding the discovery lease',
+    )
+    expect(outcome).not.toContain('every pass')
+  })
+
+  it('does not present an older daemon\'s unstamped deferred zeroes as a measurement', () => {
+    const outcome = formatSweepOutcome({
+      state: 'healthy',
+      consecutiveFailures: 0,
+      failureThreshold: 3,
+      candidates: 0,
+      dispatched: 0,
+      skipped: 0,
+      discoveryDeferred: 'sweep-in-flight',
+    })
+
+    expect(outcome).toBe(
+      'not attributable (legacy deferred report has counts without an enumeration timestamp; ' +
+      'the most recent pass deferred to another process holding the discovery lease)',
+    )
+    expect(outcome).not.toContain('candidate(s)')
+  })
+
+  it('renders a rejected count snapshot as unknown rather than never enumerated', () => {
+    const outcome = formatSweepOutcome({
+      state: 'healthy',
+      consecutiveFailures: 0,
+      failureThreshold: 3,
+      discoveryDeferred: 'sweep-in-flight',
+      enumerationCountsInvalid: true,
+    })
+
+    expect(outcome).toBe(
+      'not attributable (the report supplied an incomplete or invalid count snapshot; ' +
+      'whether an earlier pass enumerated is unknown)',
+    )
+    expect(outcome).not.toContain('nothing has enumerated successfully yet')
+  })
+})
+
 describe('factory diagnose --deployed (#295)', () => {
   it('reports a healthy deployed instance and exits zero without any credential', async () => {
     const seen: string[] = []
@@ -765,4 +817,3 @@ describe('factory diagnose --deployed (#295)', () => {
     }
   })
 })
-

src/cli/diagnose.ts

@@ -327,28 +327,53 @@ function verdictFor(diagnosis: Omit<DeployedFactoryDiagnosis, 'verdict' | 'dispa
       'dispatching: readinessReconcile is healthy' +
       (readiness?.intervalMs ? ` on a ${formatDuration(readiness.intervalMs)} cadence` : '') +
       `, and the event listener is ${health.eventListener?.state ?? 'unknown'}.` +
-      ` Last completed sweep: ${formatSweepOutcome(readiness)}.`,
+      ` Last enumerating sweep: ${formatSweepOutcome(readiness)}.`,
   }
 }
 
 /**
- * The last completed sweep, as a phrase that keeps zero and absent apart (#355).
+ * The last enumerating sweep, as a phrase that keeps zero and absent apart (#355).
  *
  * `candidates: 0` says discovery pulled nothing and the bug is upstream of
- * eligibility; no `candidates` at all says this instance has not finished a
+ * eligibility; no `candidates` at all says this instance has not enumerated a
  * sweep — or predates the counters — and says nothing about either. Rendering
  * both as `0` would recreate the ambiguity the field exists to remove.
  */
 export function formatSweepOutcome(
   readiness: FactoryPublicReadinessReconcileHealth | undefined,
 ): string {
+  if (readiness?.enumerationCountsInvalid) {
+    return 'not attributable (the report supplied an incomplete or invalid count snapshot; ' +
+      'whether an earlier pass enumerated is unknown)'
+  }
   if (!readiness || readiness.candidates === undefined) {
-    return 'not reported (no sweep has completed, or this instance predates the counters)'
+    // A deferred pass publishes the marker with no counts. It proves only why
+    // the LATEST pass did not enumerate: an earlier startup attempt may have
+    // failed before it could publish any outcome (#359 review).
+    return readiness?.discoveryDeferred
+      ? 'nothing has enumerated successfully yet — the most recent pass deferred ' +
+        'to another process holding the discovery lease'
+      : 'not reported (no sweep has enumerated, or this instance predates the counters)'
+  }
+  if (readiness.discoveryDeferred && readiness.lastEnumeratedAtMs === undefined) {
+    // The immediately preceding producer overwrote its trio with zeroes on a
+    // deferral and had no enumeration timestamp. Those values cannot be
+    // attributed to a real provider read, so label the record as legacy/unknown
+    // instead of presenting it under "Last enumerating sweep" (#359 review).
+    return 'not attributable (legacy deferred report has counts without an enumeration timestamp; ' +
+      'the most recent pass deferred to another process holding the discovery lease)'
   }
   return `${readiness.candidates} candidate(s), ${readiness.dispatched ?? 0} dispatched, ` +
     `${readiness.skipped ?? 0} skipped` +
     (readiness.discoveryDeferred
-      ? ' — it deferred to another process holding the discovery lease and enumerated nothing'
+      // Name the instant, not just "an earlier pass" (#359 review): retained
+      // counts sit beside an ever-fresh `lastCompletedAtMs`, so without this
+      // an operator cannot tell a measurement one interval old from one days
+      // old, and the staleness is the whole reason to say anything at all.
+      ? `${readiness.lastEnumeratedAtMs === undefined
+          ? ''
+          : ` measured ${formatInstant(readiness.lastEnumeratedAtMs)}`} — the most recent pass deferred ` +
+        'to another process holding the discovery lease and enumerated nothing'
       : '')
 }
 
@@ -503,6 +528,7 @@ export function renderDeployedDiagnosis(diagnosis: DeployedFactoryDiagnosis): st
       // #355. `candidates === 0` and an absent `candidates` are opposite
       // diagnoses, so the renderer must not collapse them into one dash.
       lines.push(`    last sweep         : ${formatSweepOutcome(readiness)}`)
+      lines.push(`    lastEnumeratedAt   : ${formatInstant(readiness.lastEnumeratedAtMs)}`)
       if (readiness.skipReasons) {
         lines.push(`    skip reasons       : ${formatSkipReasons(readiness.skipReasons)}`)
       }

src/orchestrator/factory.test.ts

@@ -11956,8 +11956,10 @@ describe('FactoryLoop', () => {
     const watchStatePath = join(root, 'state.json')
     const state = () => new FileStateStore({ batchSize: 1, watchStatePath })
     const gate = Promise.withResolvers<void>()
+    const spawnStarted = Promise.withResolvers<void>()
     class HangingSpawnFleetClient extends RemoteLifecycleFleetClient {
       override async spawn(input: SpawnInput): Promise<SpawnResult> {
+        spawnStarted.resolve()
         await gate.promise
         return super.spawn(input)
       }
@@ -11980,16 +11982,17 @@ describe('FactoryLoop', () => {
       const key = dispatchIssueIdentity(decision.issue)
       const dispatched = factory.dispatch(decision)
 
-      const claimed = await vi.waitFor(async () => {
-        const lifecycle = await state().getDispatchLifecycle('factory-test', key)
-        expect(lifecycle).toMatchObject({ phase: 'dispatching' })
-        return lifecycle!
-      }, { timeout: 6_000 })
+      // `phase: dispatching` is also persisted before the spawn starts. Wait
+      // for the fleet call itself so this test exercises a genuinely late
+      // placement rather than racing an earlier ownership fence (#359 CI).
+      await spawnStarted.promise
+      const claimed = await state().getDispatchLifecycle('factory-test', key)
+      expect(claimed).toMatchObject({ phase: 'dispatching' })
 
       // Another owner reclaims the row once this process's lease has lapsed.
       // Claiming on a future clock is what lets it past the live-lease guard.
       const takeover = await state().claimDispatchLifecycle(
-        'factory-test', key, claimed, 'other-owner', Date.now() + 10 * 60_000, 10 * 60_000,
+        'factory-test', key, claimed!, 'other-owner', Date.now() + 10 * 60_000, 10 * 60_000,
       )
       expect(takeover.acquired).toBe(true)