diff --git a/docs/deployed-diagnostics.md b/docs/deployed-diagnostics.md index f4521bd3..ae2140cf 100644 --- a/docs/deployed-diagnostics.md +++ b/docs/deployed-diagnostics.md @@ -185,6 +185,27 @@ logic of its own by design: the boundary lives in one place, in this repo, with not running the loop at all, or it predates #351 — on a current build a hung call fails within `relayfileOperationTimeoutMs`. +- **`treeReads` / `emptyTreeReads`** — the case a timeout cannot catch. A mount that starts serving + *empty* trees instead of hanging raises no timeout, no failure and no `lastError`: the sweep + completes `healthy` and dispatches nothing, which on every other field is indistinguishable from a + workspace that simply has no ready work. + + Read them as a pair, against `candidates`. An empty read on its own is ordinary — a healthy sweep + lists two path forms per repo and only one of them exists. The fault is + `emptyTreeReads === treeReads` with `treeReads > 0`: the mount served nothing at all. So + `candidates: 0, treeReads: 3, emptyTreeReads: 1` is an empty workspace, and + `candidates: 0, treeReads: 3, emptyTreeReads: 3` is a silent mount. + + `factory diagnose --deployed` makes that reading for you: it renders a `tree reads` line and + folds the verdict into the "Last enumerating sweep" sentence, so an all-empty pass says + `the mount served nothing at all` rather than leaving a zero `candidates` to speak for itself. + + Both numbers count only the reads the readiness sweep's own discovery pass issued. In live mode + event drains and completion timers list trees too, and a populated lookup landing in the + denominator would make `emptyTreeReads < treeReads` on a sweep whose every discovery read was + empty — masking the fault. So a sweep whose roots all came from the discovery cache reports + `treeReads: 0`, which claims nothing in either direction. + ### Why `ok` stays `true` while `status` goes amber `/healthz` is the Cloudflare **Container ping endpoint** (`pingEndpoint = 'localhost/healthz'` in the diff --git a/src/cli/diagnose.test.ts b/src/cli/diagnose.test.ts index 69e18d83..798b684b 100644 --- a/src/cli/diagnose.test.ts +++ b/src/cli/diagnose.test.ts @@ -123,6 +123,74 @@ describe('formatSweepOutcome (#359)', () => { ) expect(outcome).not.toContain('nothing has enumerated successfully yet') }) + + // MUST-FIRE (#363 review, codex P1). The numbers reaching `/healthz` is only + // half of getting the signal to the operator: `candidates: 0` with every + // tree read empty and `candidates: 0` with content served are opposite + // diagnoses, and this sentence is where a deployed operator meets them. It + // is also the sentence the verdict line embeds, so the reading travels with + // the "dispatching" claim it qualifies. + it('names a silent mount rather than leaving a zero candidate count to speak for itself', () => { + const outcome = formatSweepOutcome({ + state: 'healthy', + consecutiveFailures: 0, + failureThreshold: 3, + candidates: 0, + dispatched: 0, + skipped: 0, + treeReads: 3, + emptyTreeReads: 3, + }) + + expect(outcome).toContain('0 candidate(s)') + expect(outcome).toContain('every one of 3 tree read(s) came back empty') + expect(outcome).toContain('the mount served nothing at all') + }) + + // MUST-NOT-FIRE, and it is the reason this is a pair rather than a count: a + // healthy sweep lists two path forms per repo and only one exists, so an + // empty read is ORDINARY. A renderer that shouted on any empty read would + // shout on every healthy instance, and an operator would learn to ignore it. + it('stays quiet when the mount served content, and when no read was made', () => { + const emptyWorkspace = formatSweepOutcome({ + state: 'healthy', + consecutiveFailures: 0, + failureThreshold: 3, + candidates: 0, + dispatched: 0, + skipped: 0, + treeReads: 3, + emptyTreeReads: 1, + }) + expect(emptyWorkspace).not.toContain('served nothing at all') + expect(emptyWorkspace).toContain('1/3 tree read(s) empty') + + // An incremental sweep that answered every root from the discovery cache + // issued no read at all. A ratio over zero reads is not a fact about the + // mount, so it claims neither direction. + const noReads = formatSweepOutcome({ + state: 'healthy', + consecutiveFailures: 0, + failureThreshold: 3, + candidates: 0, + dispatched: 0, + skipped: 0, + treeReads: 0, + emptyTreeReads: 0, + }) + expect(noReads).toBe('0 candidate(s), 0 dispatched, 0 skipped') + + // A producer that predates the pair says nothing about it either. + const olderProducer = formatSweepOutcome({ + state: 'healthy', + consecutiveFailures: 0, + failureThreshold: 3, + candidates: 0, + dispatched: 0, + skipped: 0, + }) + expect(olderProducer).toBe('0 candidate(s), 0 dispatched, 0 skipped') + }) }) describe('factory diagnose --deployed (#295)', () => { diff --git a/src/cli/diagnose.ts b/src/cli/diagnose.ts index aec73d63..4e7a1dbf 100644 --- a/src/cli/diagnose.ts +++ b/src/cli/diagnose.ts @@ -366,6 +366,7 @@ export function formatSweepOutcome( } return `${readiness.candidates} candidate(s), ${readiness.dispatched ?? 0} dispatched, ` + `${readiness.skipped ?? 0} skipped` + + formatTreeReadReading(readiness) + (readiness.discoveryDeferred // Name the instant, not just "an earlier pass" (#359 review): retained // counts sit beside an ever-fresh `lastCompletedAtMs`, so without this @@ -378,6 +379,32 @@ export function formatSweepOutcome( : '') } +/** + * The tree-read pair, turned into the sentence an operator needs (#363 review). + * + * The numbers reaching `/healthz` is half the fix; the other half is that + * `candidates: 0, treeReads: 3, emptyTreeReads: 3` and + * `candidates: 0, treeReads: 3, emptyTreeReads: 1` mean opposite things and + * nothing on this surface said which was which. The first is a mount serving + * nothing at all — dispatch is dead upstream of eligibility; the second is a + * workspace with no ready work. + * + * Silent about a zero `treeReads`: a sweep that issued no enumerating read + * (deferred, or shed) has nothing to report here, and a ratio over zero reads + * is not a fact about the mount. + */ +export function formatTreeReadReading( + readiness: FactoryPublicReadinessReconcileHealth | undefined, +): string { + const treeReads = readiness?.treeReads + const emptyTreeReads = readiness?.emptyTreeReads + if (treeReads === undefined || emptyTreeReads === undefined || treeReads === 0) return '' + return emptyTreeReads === treeReads + ? ` — every one of ${treeReads} tree read(s) came back empty: the mount served nothing at all,` + + ' so a zero candidate count here is not evidence the workspace is empty' + : ` (${emptyTreeReads}/${treeReads} tree read(s) empty — the mount served content)` +} + /** The skip breakdown, ordered as the record carries it. */ export function formatSkipReasons(counts: Record): string { const entries = Object.entries(counts).filter(([, count]) => count > 0) @@ -549,6 +576,17 @@ export function renderDeployedDiagnosis(diagnosis: DeployedFactoryDiagnosis): st }`, ) } + // Rendered whenever the producer reports the pair, zeroes included: the + // raw numbers are what an operator diffs across two samples, and the + // reading beside them is what they act on (#363 review). + if (readiness.treeReads !== undefined && readiness.emptyTreeReads !== undefined) { + lines.push( + ` tree reads : ${readiness.treeReads} served, ${readiness.emptyTreeReads} empty` + + (readiness.treeReads > 0 && readiness.emptyTreeReads === readiness.treeReads + ? ' — SILENT MOUNT: it served nothing at all' + : ''), + ) + } } const capacity = health.dispatchCapacity if (capacity) { diff --git a/src/orchestrator/factory.test.ts b/src/orchestrator/factory.test.ts index c8548e25..fd71bae3 100644 --- a/src/orchestrator/factory.test.ts +++ b/src/orchestrator/factory.test.ts @@ -13498,7 +13498,12 @@ describe('FactoryLoop', () => { // Self-healing: a later cycle STARTED while the dependency is still // hung. This is the number that stayed frozen for 22 minutes. expect(status.counters.readinessReconcileSweeps ?? 0).toBeGreaterThan(sweepsWhileHung) - }, { timeout: 5_000 }) + // ...and a later cycle also FINISHED. A second independent failure is + // what proves `#runOnceInFlight` was cleared: had it still held the + // wedged promise, cycle two would have coalesced onto it and never + // settled, leaving this at exactly 1 forever (#351 review). + expect(status.readinessReconcile?.consecutiveFailures ?? 0).toBeGreaterThanOrEqual(2) + }, { timeout: 8_000 }) // And it recovers on its own once the dependency answers again — no // restart, which is the only thing that cleared this in production. @@ -13516,6 +13521,255 @@ describe('FactoryLoop', () => { // Two sequential `vi.waitFor` windows do not fit the suite's 5s default. }, 20_000) + // The unwind is what makes the bound a fix rather than a shorter hang: the + // #296 sweep deadline rejects the wait while `runOnce()` keeps the durable + // lease, so the next cycle finds the workspace owned and defers. Asserted + // directly rather than inferred from "the next cycle ran" (#351 review). + it('releases the discovery lease when a hung read aborts the sweep', async () => { + const mount = new HangingListTreeMount() + const stateStore = new InMemoryStateStore({ batchSize: 2 }) + const factory = createFactory(config({ issueSource: 'github' }), { + mount, + stateStore, + fleet: new FakeFleetClient(), + triage: new StaticTriage(), + githubWriteback: new RecordingGithubWriteback(), + logger: { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }, + }) + + await factory.start({ + mode: 'live', + liveSubscription: { + transport: 'subscribe', + reconcileIntervalMs: 20, + reconcileTimeoutMs: 60_000, + relayfileOperationTimeoutMs: 50, + }, + }) + try { + mount.hangListTree = true + await mount.hangStarted + await vi.waitFor(() => { + expect(factory.status().readinessReconcile?.consecutiveFailures ?? 0) + .toBeGreaterThanOrEqual(1) + }, { timeout: 5_000 }) + + // Stop first so no live cycle is holding the lease legitimately — the + // probe would otherwise race the 20ms loop. `stop()` has no release of + // its own (the fence's finally is the only `releaseDiscoverySweep` + // call site), so a lease free here was freed by the aborted sweep. + await factory.stop() + const probe = await stateStore.claimDiscoverySweep( + 'factory-test', 'probe-owner', Date.now(), 1_000, + ) + expect(probe).toMatchObject({ acquired: true }) + expect(probe.reclaimedLease).toBeUndefined() + } finally { + mount.release() + await factory.stop() + } + }, 20_000) + + // The companion to the timeout, asked for on #351 and missing from #354. + // + // A bounded read that HANGS is now loud. A bounded read the mount ANSWERS + // WITH NOTHING is not: no timeout, no failure, no `lastError`, and a sweep + // that completes `healthy` having dispatched nothing. `candidates: 0` + // cannot separate that from a workspace with no ready work, so the two + // states that both mean "dispatch is dead" look identical on the surface. + describe('empty reads versus timeouts', () => { + // Isolated registry and heartbeat per factory. The config default points + // every instance at one shared path, so a live-mode fixture that writes + // there leaks rows into whatever test runs next. + const startEmptyReadFactory = async (mount: CountingEventsMount) => { + const root = await mkdtemp(join(tmpdir(), 'factory-empty-reads-')) + const factory = createFactory(config({ + issueSource: 'github', + loop: { + heartbeatPath: join(root, 'heartbeat.json'), + registryPath: join(root, 'registry.json'), + }, + }), { + mount, + stateStore: new InMemoryStateStore({ batchSize: 2 }), + fleet: new FakeFleetClient(), + triage: new StaticTriage(), + githubWriteback: new RecordingGithubWriteback(), + logger: { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }, + }) + await factory.start({ + mode: 'live', + liveSubscription: { transport: 'subscribe', reconcileIntervalMs: 20 }, + }) + return { + factory, + heartbeatPath: join(root, 'heartbeat.json'), + cleanup: async () => { await rm(root, { recursive: true, force: true }) }, + } + } + + // MUST-FIRE for the scoping (#363 review, codex P2). The counters used to + // increment on EVERY served `listTree` in the process, and in live mode + // event drains and completion timers issue those concurrently with + // `runOnce()`. A populated lookup landing in the denominator makes + // `emptyTreeReads < treeReads` on a sweep whose every discovery read was + // empty, which erases exactly the signal the pair exists to raise; an + // unrelated empty lookup distorts it the other way. + // + // One-shot rather than live on purpose: the concurrency is what makes the + // bug real, but a fixed sweep is what makes the arithmetic assertable. + // This run serves seven tree reads, and only the two the discovery pass + // itself issued may appear in the pair. + it('counts only the discovery pass\'s own reads, not every list in the process', async () => { + class MixedReadMount extends CountingEventsMount { + readonly listed: Array<{ prefix: string; count: number }> = [] + + constructor() { + super() + this.setSubRoot('/linear/issues', 'absent') + // Enumeration: one path form exists, the other does not. That empty + // read is the ordinary one the pair is designed to tolerate. + this.files.set('/github/repos/AgentWorkforce/pear/issues/by-id/1.json', { + content: githubIssueFile(1, { labels: ['factory'] }), + }) + // Reached only by the dispatch path's own lookups, never by + // discovery — the reads that must stay outside the ratio. + this.files.set('/github/repos/AgentWorkforce/pear/pulls/7/metadata.json', { + content: prFile(7, { title: 'GitHub factory issue 1', head_ref: 'gh-1', state: 'OPEN' }), + }) + } + + override async listTree(prefix: string): Promise { + const paths = await super.listTree(prefix) + this.listed.push({ prefix, count: paths.length }) + return paths + } + } + + const mount = new MixedReadMount() + const factory = createFactory(config({ issueSource: 'github' }), { + mount, + stateStore: new InMemoryStateStore({ batchSize: 2 }), + fleet: new FakeFleetClient(), + triage: new StaticTriage(), + githubWriteback: new RecordingGithubWriteback(), + logger: { debug: vi.fn(), info: vi.fn(), warn: vi.fn(), error: vi.fn() }, + }) + const report = await factory.runOnce() + expect(report.dispatched).toHaveLength(1) + + const isEnumerationRoot = (prefix: string) => + prefix === '/github/repos/AgentWorkforce/pear/issues' || + prefix === '/github/repos/AgentWorkforce__pear/issues' + const outsideDiscovery = mount.listed.filter(({ prefix }) => !isEnumerationRoot(prefix)) + + // The fixture earns the assertion below: the mount really did serve + // reads that were not the discovery pass, and at least one came back + // empty — the exact shape that used to inflate `emptyTreeReads`. + expect(outsideDiscovery.length).toBeGreaterThanOrEqual(1) + expect(outsideDiscovery.some(({ count }) => count === 0)).toBe(true) + + // The discovery pass listed two path forms, one of which exists. That + // is the whole ratio; unconditional counting reported 7 and 4 here. + expect(report.treeReads).toBe(2) + expect(mount.listed.length).toBeGreaterThan(report.treeReads ?? 0) + // MUST-NOT-FIRE, the opposite direction: scoping the counters must not + // silently stop counting. The enumeration's own empty read is still in + // the numerator, so the ordinary case stays visible and a later + // all-empty sweep is still distinguishable from this one. + expect(report.emptyTreeReads).toBe(1) + expect(factory.status().counters.relayfileEmptyTreeReads).toBe(1) + }, 20_000) + + it('counts a served-but-empty read so a silent mount is distinguishable', async () => { + // Every tree read is served, promptly, with nothing in it. + class EmptyTreeMount extends CountingEventsMount { + constructor() { + super() + this.setSubRoot('/linear/issues', 'absent') + } + + override async listTree(_prefix: string): Promise { + return [] + } + } + + const mount = new EmptyTreeMount() + const { factory, heartbeatPath, cleanup } = await startEmptyReadFactory(mount) + try { + await vi.waitFor(() => { + const readiness = factory.status().readinessReconcile + // The surface an operator reads is green in every existing field... + expect(readiness?.state).toBe('healthy') + expect(readiness?.consecutiveFailures).toBe(0) + expect(readiness?.lastError).toBeUndefined() + expect(readiness?.candidates).toBe(0) + // ...and this pair is what says why. Not the empty count alone — + // an empty read is ordinary; EVERY read empty is the fault. + expect(readiness?.treeReads ?? 0).toBeGreaterThanOrEqual(1) + expect(readiness?.emptyTreeReads).toBe(readiness?.treeReads) + }, { timeout: 5_000 }) + + expect(factory.status().counters.relayfileEmptyTreeReads ?? 0) + .toBeGreaterThanOrEqual(1) + + // ...and it reaches the ONLY surface a deployed operator can read. + // `factory diagnose --deployed` goes to the unauthenticated /healthz + // route, which serves this projection of this file — so a pair that + // stops at the in-process `status()` object above does not exist + // where the fault is met (#363 review, codex P1). + await vi.waitFor(async () => { + const heartbeat = await readFactoryLoopHeartbeat(heartbeatPath) + const published = publicHealthFromHeartbeat(heartbeat!, { nowMs: Date.now() }) + .readinessReconcile + expect(published?.treeReads ?? 0).toBeGreaterThanOrEqual(1) + expect(published?.emptyTreeReads).toBe(published?.treeReads) + }, { timeout: 5_000 }) + } finally { + await factory.stop() + await cleanup() + } + }, 20_000) + + // The control, and it earned its place: the first version of this signal + // was a bare empty-read count, and this test caught it firing on a + // perfectly healthy sweep. A healthy sweep lists two path forms per repo + // and only one of them exists, so `emptyTreeReads >= 1` is normal and + // only the ratio discriminates. + it('control: a mount serving content reports zero empty reads', async () => { + class PopulatedTreeMount extends CountingEventsMount { + constructor() { + super() + this.setSubRoot('/linear/issues', 'absent') + // Present in the tree, but not ready — so `candidates` still lands + // at 0 and only `emptyReads` separates this from the case above. + this.files.set( + '/github/repos/AgentWorkforce/pear/issues/by-id/1.json', + { content: { number: 1, title: 'not ready', state: 'open', labels: [] } }, + ) + } + } + + const mount = new PopulatedTreeMount() + const { factory, cleanup } = await startEmptyReadFactory(mount) + try { + await vi.waitFor(() => { + expect(factory.status().readinessReconcile?.lastEnumeratedAtMs).toBeDefined() + }, { timeout: 5_000 }) + + const readiness = factory.status().readinessReconcile + expect(readiness?.state).toBe('healthy') + // Content was served, so not every read was empty — which is exactly + // the comparison an operator makes against a zero `candidates`. + expect(readiness?.treeReads ?? 0).toBeGreaterThanOrEqual(1) + expect(readiness?.emptyTreeReads ?? 0).toBeLessThan(readiness?.treeReads ?? 0) + } finally { + await factory.stop() + await cleanup() + } + }, 20_000) + }) + // With the real cloud mount the TRANSPORT deadline wins the race by design, // and the mount does not know which phase it was serving — so without the // orchestrator enriching it, `lastError` names the call but not the context diff --git a/src/orchestrator/factory.ts b/src/orchestrator/factory.ts index 642e2b41..719470f0 100644 --- a/src/orchestrator/factory.ts +++ b/src/orchestrator/factory.ts @@ -1,3 +1,4 @@ +import { AsyncLocalStorage } from 'node:async_hooks' import { randomUUID } from 'node:crypto' import { readFile } from 'node:fs/promises' import { dirname, isAbsolute, resolve } from 'node:path' @@ -648,6 +649,27 @@ export function createFactory(config: FactoryConfig, ports: FactoryPorts): Facto return new FactoryLoop(FactoryConfigSchema.parse(config), ports) } +/** + * The discovery pass a tree read was issued by, carried per async call (#363 + * review, CodeRabbit). + * + * `#discoverySweepEpoch` says a sweep is in flight; it cannot say the read in + * hand belongs to it. In live mode an event drain reaches the very same + * enumeration helpers — `#handlePrChange` -> `#advanceMergedPrToDone` -> + * `#findMergeAdvanceIssueForPr` -> `#githubIssuePaths()` is the concrete path — + * so a drain's full-root walk would land in a concurrent sweep's ratio while + * measuring a different instant. That is enough to hide a mount that went + * silent mid-sweep. + * + * A drain does not inherit this store: its continuation begins at the + * subscription callback, outside the `run()` below. Threading an epoch argument + * through `#ingestGithubIssues` / `#handleGithubIssueChange` / + * `#findGithubIssueMirror` / `#loadLinearMirrorCandidates` would express the + * same fact and put a parameter on every hot path that must never be passed + * wrong. + */ +const discoveryEnumerationPass = new AsyncLocalStorage<{ epoch: number }>() + export class FactoryLoop implements Factory { readonly #config: FactoryConfig readonly #mount: MountClient @@ -866,6 +888,9 @@ export class FactoryLoop implements Factory { */ #readinessReconcileLastSweep?: { candidates: number + /** Served tree reads, and how many were empty. Held even at zero. */ + treeReads: number + emptyTreeReads: number dispatched: number skipped: number skipReasons: Partial> @@ -1002,6 +1027,10 @@ export class FactoryLoop implements Factory { #discoveryOverloadError?: unknown /** Relayfile operations this sweep has been shed on. */ #discoverySweepOverloads = 0 + /** Tree reads this sweep issued that the backend served (#351 follow-up). */ + #discoverySweepTreeReads = 0 + /** How many of those were served with zero entries. */ + #discoverySweepEmptyTreeReads = 0 /** * The longest `Retry-After` any operation in this sweep advertised. * @@ -2745,6 +2774,8 @@ export class FactoryLoop implements Factory { this.#discoverySweepLeaseLost = false this.#discoveryOverloadError = undefined this.#discoverySweepOverloads = 0 + this.#discoverySweepTreeReads = 0 + this.#discoverySweepEmptyTreeReads = 0 this.#discoverySweepRetryAfterSeconds = undefined this.#discoverySweepProgress = false this.#startDiscoverySweepRenewal(claim.lease.epoch) @@ -2828,6 +2859,8 @@ export class FactoryLoop implements Factory { this.#discoverySweepStartedAtMs = undefined this.#discoveryOverloadError = undefined this.#discoverySweepOverloads = 0 + this.#discoverySweepTreeReads = 0 + this.#discoverySweepEmptyTreeReads = 0 this.#discoverySweepRetryAfterSeconds = undefined this.#discoverySweepProgress = false // This sweep is over either way (committed, deferred, or lease lost) — @@ -2976,12 +3009,19 @@ export class FactoryLoop implements Factory { this.#dependencyGithubPathsByIdentity = undefined this.#dependencyLinearTreeLoaded = false const issueSource = await this.#issueSource() + // The sweep's own discovery pass, and the only region whose full-root + // walks may enter the tree-read ratio (#363 review). Everything reached + // from here inherits the marker; a concurrently running drain does not. + const enumerate = (fn: () => Promise): Promise => + this.#discoverySweepEpoch === undefined + ? fn() + : discoveryEnumerationPass.run({ epoch: this.#discoverySweepEpoch }, fn) if (issueSource === 'linear') { - await this.#ingestGithubIssues({ dryRun }) + await enumerate(() => this.#ingestGithubIssues({ dryRun })) } else { await this.#ensureGithubIngestionReady() } - const paths = await this.#readyIssuePaths() + const paths = await enumerate(() => this.#readyIssuePaths()) const orphanRecovery = issueSource === 'github' ? await this.#githubOrphanRecoveryContext(dryRun) : undefined @@ -3291,6 +3331,10 @@ export class FactoryLoop implements Factory { dispatched, skipped, dryRun, + // Read before `#runOnceWithDiscoveryFence`'s finally resets them: this + // is still inside that try, so the counts are this sweep's own. + treeReads: this.#discoverySweepTreeReads, + emptyTreeReads: this.#discoverySweepEmptyTreeReads, slackDegraded: this.#slackDegraded, ...(orphanRecoveryDegraded ? { orphanRecoveryDegraded } : {}), } @@ -4263,7 +4307,15 @@ export class FactoryLoop implements Factory { // that expects a specific PR to appear, or an escalation/comment-replay // scan that must not miss a marker or reply that landed after the cache // was populated. Those callers must omit `cache` and pay for a fresh list. - async #listRelayfileTree(prefix: string, phase: string, opts: { cache?: boolean } = {}): Promise { + // + // `enumeration` marks the call sites that ARE the readiness sweep's + // discovery pass — a full-root walk looking for candidate work. Only those + // feed the tree-read pair below, and only while a sweep holds the lease. + async #listRelayfileTree( + prefix: string, + phase: string, + opts: { cache?: boolean; enumeration?: boolean } = {}, + ): Promise { if (this.#discoverySweepLeaseLost) { throw new Error('discovery sweep lease was lost; refusing another tree request') } @@ -4280,6 +4332,46 @@ export class FactoryLoop implements Factory { logStart: true, logComplete: true, }) + // #351 follow-up: tree reads the backend SERVED, and how many of them it + // answered with nothing. + // + // The per-call deadline made a hung dependency loud. This is its + // companion: a mount that starts returning empty trees instead of hanging + // raises no timeout, no failure and no `lastError`, and produces a sweep + // that completes `healthy` having dispatched nothing. + // + // BOTH numbers, because one is not a signal. A healthy sweep lists two + // path forms per repo and only one of them exists, so an empty read is + // ordinary and a bare count of them fires constantly. What separates the + // fault is the RATIO: `emptyTreeReads === treeReads` means the mount + // served nothing at all, which `candidates: 0` cannot distinguish from a + // workspace that simply has no ready work. + // + // SCOPED TWICE, and both guards are load-bearing (#363 review, codex P2). + // The ratio is only readable if every read in it came from the same + // question. In live mode a Slack identity lookup, a PR-confirmation poll + // or a comment-replay scan can run concurrently with `runOnce()` — each is + // a `listTree`, none is discovery, and one populated result among them + // makes `emptyTreeReads < treeReads` on an all-empty sweep, silently + // erasing exactly the signal this pair exists to raise. `enumeration` + // keeps the numerator and denominator to the discovery pass; the epoch + // check keeps a discovery walk issued outside any sweep — startup + // backfill, most obviously — out of a sweep's totals. + // `enumeration` says this is a full-root discovery walk rather than a point + // lookup; the context says THIS sweep's discovery pass is what issued it. + // Both, because either alone admits a read the ratio cannot use. Compared + // by value rather than presence: an absent store and an absent epoch are + // both `undefined` and must not read as a match. + const issuingPass = discoveryEnumerationPass.getStore() + if (opts.enumeration && + issuingPass !== undefined && + issuingPass.epoch === this.#discoverySweepEpoch) { + this.#discoverySweepTreeReads += 1 + if (paths.length === 0) { + this.#increment('relayfileEmptyTreeReads') + this.#discoverySweepEmptyTreeReads += 1 + } + } if (opts.cache) await this.#rememberDiscoveryTree(prefix, paths) return paths } @@ -5116,6 +5208,8 @@ export class FactoryLoop implements Factory { this.#readinessReconcileLastSweepDeferred = undefined this.#readinessReconcileLastSweep = { candidates: report.pulled.length, + treeReads: report.treeReads ?? 0, + emptyTreeReads: report.emptyTreeReads ?? 0, dispatched: report.dispatched.length, skipped: report.skipped.length, skipReasons: factorySweepSkipReasonCounts(report.skipped), @@ -5213,6 +5307,13 @@ export class FactoryLoop implements Factory { ...(this.#readinessReconcileLastSweep ? { candidates: this.#readinessReconcileLastSweep.candidates, + // Unconditional for the same reason `dispatchFailures` is: these + // are only meaningful as a pair, and only a published zero lets a + // reader see that `emptyTreeReads < treeReads` — i.e. that the + // mount served real content and a zero `candidates` beside it means + // an empty workspace, not a silent mount (#351 follow-up). + treeReads: this.#readinessReconcileLastSweep.treeReads, + emptyTreeReads: this.#readinessReconcileLastSweep.emptyTreeReads, dispatched: this.#readinessReconcileLastSweep.dispatched, skipped: this.#readinessReconcileLastSweep.skipped, ...(Object.keys(this.#readinessReconcileLastSweep.skipReasons).length > 0 @@ -7459,7 +7560,7 @@ export class FactoryLoop implements Factory { const candidates: LinearIssue[] = [] let scanned = 0 let lastProgressAtMs = startedAtMs - for (const path of await this.#listRelayfileTree(ISSUE_ROOT, 'GitHub mirror candidate loading', { cache: true })) { + for (const path of await this.#listRelayfileTree(ISSUE_ROOT, 'GitHub mirror candidate loading', { cache: true, enumeration: true })) { await this.#refreshLiveHeartbeatIfDue() if (!isLinearIssueMirrorCandidatePath(path)) { continue @@ -7513,7 +7614,7 @@ export class FactoryLoop implements Factory { } else { pathBatches = [] for (const root of roots) { - pathBatches.push(await this.#listRelayfileTree(root, 'GitHub issue ingestion', { cache: true })) + pathBatches.push(await this.#listRelayfileTree(root, 'GitHub issue ingestion', { cache: true, enumeration: true })) } this.#increment('githubIssueIndexFallbacks') } @@ -8014,6 +8115,10 @@ export class FactoryLoop implements Factory { // The pass-scoped flag also lets every later blocked issue reuse the // resulting dependency index instead of rescanning the full tree. this.#dependencyLinearTreeLoaded = true + // Cached like the enumeration walks, but deliberately NOT `enumeration`: + // this is a lookup for named blocker identities, not the sweep asking + // what work exists, and mixing a lookup's result into the ratio is the + // masking the pair's scoping exists to prevent (#363 review). for (const path of await this.#listRelayfileTree(ISSUE_ROOT, 'dependency blocker discovery', { cache: true })) { if (isIssueFilePath(path)) await this.#readIssue(path) } @@ -8478,7 +8583,7 @@ export class FactoryLoop implements Factory { } const pathsByKey = new Map() const canonicalPathsByKey = new Map() - for (const path of await this.#listRelayfileTree(ISSUE_ROOT, 'Linear ready issue canonical discovery', { cache: true })) { + for (const path of await this.#listRelayfileTree(ISSUE_ROOT, 'Linear ready issue canonical discovery', { cache: true, enumeration: true })) { if (isIssueFilePath(path)) { const key = keyFromPath(path) canonicalPathsByKey.set(key, path) @@ -8488,7 +8593,7 @@ export class FactoryLoop implements Factory { for (const path of await this.#listRelayfileTree( linearByStatePath('ready-for-agent'), 'Linear ready issue alias discovery', - { cache: true }, + { cache: true, enumeration: true }, )) { if (isIssueAliasFilePath(path)) { const canonicalPath = canonicalPathsByKey.get(keyFromPath(path)) diff --git a/src/orchestrator/public-health.test.ts b/src/orchestrator/public-health.test.ts index 40657546..86cb48a8 100644 --- a/src/orchestrator/public-health.test.ts +++ b/src/orchestrator/public-health.test.ts @@ -1132,4 +1132,85 @@ describe('sweep counters on the public surface (#355)', () => { expect(JSON.stringify(reread)).not.toContain('workspace-key') expect(reread?.readinessReconcile?.dispatchFailureReasons).toEqual({ other: 7 }) }) + + // MUST-FIRE (#363 review, codex P1). The tree-read pair reached the internal + // `status()` object and stopped there: `sweepOutcome()` did not read it and + // `normalizePublicHealth()` therefore stripped it, so the one surface a + // deployed operator can actually reach — the unauthenticated `/healthz` + // route behind `factory diagnose --deployed` — still could not tell a mount + // serving nothing from a workspace with nothing ready. That is the whole + // fault the pair was added for, on the only instance where it is met. + it('carries the tree-read pair onto the unauthenticated surface, and back off it', () => { + const silentMount = swept({ + candidates: 0, + dispatched: 0, + skipped: 0, + treeReads: 3, + emptyTreeReads: 3, + }) + expect(silentMount?.treeReads).toBe(3) + expect(silentMount?.emptyTreeReads).toBe(3) + + // And survives the round trip a remote reader makes: the container serves + // this block inside its heartbeat and `diagnose --deployed` re-parses it. + const reread = normalizePublicHealth({ + schemaVersion: FACTORY_PUBLIC_HEALTH_SCHEMA_VERSION, + ok: true, + status: 'ok', + stale: false, + degradedSubsystems: [], + readinessReconcile: silentMount, + }) + expect(reread?.readinessReconcile?.treeReads).toBe(3) + expect(reread?.readinessReconcile?.emptyTreeReads).toBe(3) + + // The reading that separates the two zero-candidate diagnoses survives too. + const emptyWorkspace = swept({ + candidates: 0, + dispatched: 0, + skipped: 0, + treeReads: 3, + emptyTreeReads: 1, + }) + expect(emptyWorkspace?.emptyTreeReads).toBeLessThan(emptyWorkspace?.treeReads ?? 0) + }) + + // MUST-NOT-FIRE. Half a pair is worse than no pair: `emptyTreeReads` alone + // reads as "the mount is sick" on a sweep where an empty read is ordinary, + // and `treeReads` alone says nothing about what came back. A zero pair is a + // real measurement and must NOT collapse to an absence, and a producer that + // has never heard of the fields must keep the trio it does publish. + it('publishes the pair whole, or not at all', () => { + // A sweep that issued no enumerating read at all: zeroes, not absences. + const noReads = swept({ candidates: 0, dispatched: 0, skipped: 0, treeReads: 0, emptyTreeReads: 0 }) + expect(noReads?.treeReads).toBe(0) + expect(Object.hasOwn(noReads ?? {}, 'emptyTreeReads')).toBe(true) + + // Half a pair from a producer we do not understand: both go. + const halfPair = swept({ candidates: 0, dispatched: 0, skipped: 0, treeReads: 4 }) + expect(Object.hasOwn(halfPair ?? {}, 'treeReads')).toBe(false) + expect(Object.hasOwn(halfPair ?? {}, 'emptyTreeReads')).toBe(false) + // ...and the trio it DID publish is untouched, which is the whole reason + // this pair is not joined to it. + expect(halfPair).toMatchObject({ candidates: 0, dispatched: 0, skipped: 0 }) + + // Arithmetically impossible: more empty reads than reads. Publishing the + // ratio anyway would hand a reader a fabricated silent-mount verdict. + const impossible = swept({ candidates: 0, dispatched: 0, skipped: 0, treeReads: 2, emptyTreeReads: 3 }) + expect(Object.hasOwn(impossible ?? {}, 'treeReads')).toBe(false) + expect(Object.hasOwn(impossible ?? {}, 'emptyTreeReads')).toBe(false) + + // Unusable numbers, and a producer that predates the pair entirely. + const rubbish = swept({ + candidates: 0, + dispatched: 0, + skipped: 0, + treeReads: Number.NaN as unknown as number, + emptyTreeReads: -1, + }) + expect(Object.hasOwn(rubbish ?? {}, 'treeReads')).toBe(false) + const olderProducer = swept({ candidates: 4, dispatched: 4, skipped: 0 }) + expect(Object.hasOwn(olderProducer ?? {}, 'treeReads')).toBe(false) + expect(olderProducer).toMatchObject({ candidates: 4, dispatched: 4, skipped: 0 }) + }) }) diff --git a/src/orchestrator/public-health.ts b/src/orchestrator/public-health.ts index b761dd15..6b56bcdd 100644 --- a/src/orchestrator/public-health.ts +++ b/src/orchestrator/public-health.ts @@ -246,6 +246,37 @@ const dispatchFailureReasonCounts = ( return Object.fromEntries(ordered.map((code) => [code, counts[code] as number])) } +/** + * The last sweep's tree reads and how many were empty, as an all-or-nothing + * pair (#351 follow-up; #363 review, codex P1). + * + * Validated as a pair because it is only readable as one. `emptyTreeReads` + * alone fires on a healthy sweep — discovery lists two path forms per repo and + * only one exists — and `treeReads` alone says nothing about what came back. + * So half a pair is dropped rather than published: a lone number here invites + * exactly the wrong reading ("some reads were empty, so the mount is sick"). + * + * `emptyTreeReads > treeReads` is arithmetically impossible and means the + * producer is not one we understand; both numbers go rather than publishing a + * ratio a reader would take at face value. + * + * Independent of the `candidates` trio in the direction that matters, for the + * same reason `dispatchFailures` is: a producer that publishes the trio and has + * never heard of this pair keeps its trio. Not the other way round — a rejected + * trio takes the pair with it, at `sweepOutcome`'s early return, because the + * pair is only ever read against `candidates` and a ratio with nothing to + * compare it to is not the signal. + */ +const treeReadOutcome = ( + status: { treeReads?: unknown; emptyTreeReads?: unknown }, +): Partial> => { + const treeReads = optionalCount('treeReads', status.treeReads) + const emptyTreeReads = optionalCount('emptyTreeReads', status.emptyTreeReads) + if (treeReads.treeReads === undefined || emptyTreeReads.emptyTreeReads === undefined) return {} + if (emptyTreeReads.emptyTreeReads > treeReads.treeReads) return {} + return { ...treeReads, ...emptyTreeReads } +} + /** * The last enumerating sweep's arithmetic, published (#355). * @@ -268,6 +299,8 @@ const sweepOutcome = ( skipReasons?: unknown dispatchFailures?: unknown dispatchFailureReasons?: unknown + treeReads?: unknown + emptyTreeReads?: unknown discoveryDeferred?: unknown lastEnumeratedAtMs?: unknown enumerationCountsInvalid?: unknown @@ -280,6 +313,8 @@ const sweepOutcome = ( | 'skipReasons' | 'dispatchFailures' | 'dispatchFailureReasons' + | 'treeReads' + | 'emptyTreeReads' | 'discoveryDeferred' | 'lastEnumeratedAtMs' | 'enumerationCountsInvalid' @@ -332,6 +367,12 @@ const sweepOutcome = ( ...(dispatchFailures.dispatchFailures !== undefined && dispatchFailureReasons ? { dispatchFailureReasons } : {}), + // The half of the outage a timeout cannot catch, carried the rest of the + // way to the unauthenticated surface (#363 review, codex P1). Independently + // optional, like `dispatchFailures`: a 0.1.73 daemon publishes the trio and + // knows nothing about this pair, and requiring it would drop that + // producer's whole sweep block. + ...treeReadOutcome(status), // Part of the same atomic snapshot as the counts: it is what dates them, // and without it retained counts have no freshness a reader can recover // (#359 review). diff --git a/src/types.ts b/src/types.ts index 4df9ed71..618b7a94 100644 --- a/src/types.ts +++ b/src/types.ts @@ -258,6 +258,22 @@ export interface FactoryReadinessReconcileStatus { * nobody yet. */ candidates?: number + /** + * Tree reads the last enumerating sweep made, and how many were served empty + * (#351 follow-up). + * + * Read as a pair, against `candidates`. An empty read on its own is ordinary + * — a healthy sweep lists two path forms per repo and only one exists. The + * fault is `emptyTreeReads === treeReads` with `treeReads > 0`: the mount + * served nothing at all, which raises no timeout, no failure and no + * `lastError`, and is otherwise indistinguishable on a `healthy` surface from + * a workspace that simply has no ready work. + * + * Optional and never defaulted, like `candidates`: absent means no sweep has + * enumerated *or* the producer predates the fields. + */ + treeReads?: number + emptyTreeReads?: number /** Work units the last enumerating sweep actually dispatched. */ dispatched?: number /** Work units the last enumerating sweep saw and declined. */ @@ -357,6 +373,25 @@ export interface FactoryPublicReadinessReconcileHealth { */ dispatchFailures?: number dispatchFailureReasons?: Partial> + /** + * Tree reads the last enumerating sweep made, and how many came back empty + * (#351 follow-up; #363 review, codex P1). + * + * The counterpart of `FactoryReadinessReconcileStatus.treeReads` on the + * UNAUTHENTICATED surface, which is where `factory diagnose --deployed` + * reads it — the fault this pair exists to name is one an operator only ever + * meets on a deployed instance, so a signal that stops at the internal + * `status()` object does not exist where it is needed. + * + * Counts only, and a pair: published together or not at all, because + * `emptyTreeReads` alone is not a signal (a healthy sweep lists two path + * forms per repo and only one exists) and `treeReads` alone says nothing. + * The fault is `emptyTreeReads === treeReads` with `treeReads > 0` beside a + * zero `candidates`: the mount served nothing at all, rather than the + * workspace having no ready work. + */ + treeReads?: number + emptyTreeReads?: number /** * When the pass the counts describe finished enumerating. Dates them — * `lastCompletedAtMs` does not, since it advances on deferred passes too. @@ -707,6 +742,17 @@ export interface IterationReport { * sweep tried to build the context and could not. */ orphanRecoveryDegraded?: 'dry-run' | 'context-unavailable' + /** + * Tree reads this sweep issued that the backend served, and how many of them + * came back with zero entries (#351 follow-up). + * + * The companion to the per-call timeout: a bounded read that hangs is loud, a + * bounded read served with nothing is not, and both end in a sweep that + * dispatches nothing. Meaningful only as a pair — an empty read is ordinary, + * `emptyTreeReads === treeReads` is the mount serving nothing at all. + */ + treeReads?: number + emptyTreeReads?: number /** A cross-process owner was already enumerating this workspace. */ discoveryDeferred?: 'sweep-in-flight' error?: { message: string; stack?: string }