diff --git a/src/orchestrator/factory.test.ts b/src/orchestrator/factory.test.ts index aced734..8e2cfb1 100644 --- a/src/orchestrator/factory.test.ts +++ b/src/orchestrator/factory.test.ts @@ -20290,6 +20290,167 @@ describe('FactoryLoop', () => { ]) }) + // The probe PR resolver walks mounted PR metadata one `readFile` at a time. + // These three tests pin the SHAPE of that walk by read count rather than by + // wall clock, because the production symptom — a sweep silent for 11m53s and + // then reported stalled — was a read count problem wearing a latency costume. + const probePrRecordReads = (mount: FakeMountClient): string[] => + mount.reads.filter((path) => path.includes('/pulls/') && !path.endsWith('_index.json')) + + const probeLinearWriteback: LinearWriteback = { + async setState() {}, + async postComment() {}, + async createIssue() { + throw new Error('not used') + }, + async verify() { + return true + }, + } + + it('scopes the probe PR mount walk to the issue repository instead of every configured repo', async () => { + // Four pull requests in EACH of three configured repositories. AR-702 is + // labelled `pear`, so its PR can only live in AgentWorkforce/pear: a scoped + // walk reads 4 records, an unscoped one reads all 12. That is the O(N) vs + // O(N x R) distinction, and with 21 live repositories it is the difference + // between a walk and a wedge. + const repos = ['AgentWorkforce/pear', 'AgentWorkforce/hoopsheet', 'AgentWorkforce/citrus'] + const files: Record = { [issuePath(702)]: issueFile(702) } + repos.forEach((repo, repoIndex) => { + const flat = repo.replace('/', '__') + for (let index = 0; index < 4; index += 1) { + const number = 7020 + repoIndex * 10 + index + files[`/github/repos/${flat}/pulls/by-id/${number}.json`] = prFile(number, { + title: `Unrelated work ${number}`, + body: '', + head_ref: `unrelated-${number}`, + state: 'OPEN', + }) + } + }) + // The one PR that actually belongs to AR-702, in the routed repository. + files['/github/repos/AgentWorkforce__pear/pulls/by-id/702.json'] = prFile(702, { + title: 'AR-702 work', + body: '', + head_ref: 'factory/ar-702-work', + state: 'OPEN', + }) + + const mount = new FakeMountClient(files) + const fleet = new FakeFleetClient() + const factory = createFactory( + config({ + repos: { + byLabel: { pear: repos[0]!, hoopsheet: repos[1]!, citrus: repos[2]! }, + byProject: {}, + keywordRules: [], + clonePaths: { [repos[0]!]: '/work/pear' }, + default: repos[0]!, + }, + }), + { + mount, + fleet, + triage: new StaticTriage(), + linear: probeLinearWriteback, + probeCloser: async (input) => ({ repo: input.repo, prNumber: input.prNumber, state: 'CLOSED' }), + }, + ) + + await factory.dispatch(await factory.triageIssue(parseLinearIssue(issuePath(702), issueFile(702)))) + fleet.emitAgentExit('ar-702-impl-pear', 'issue-done') + await flush() + + const reads = probePrRecordReads(mount) + // Scales with the routed repository's PR count, not with the repo count. + expect(reads).toHaveLength(5) + expect(reads.every((path) => path.includes('AgentWorkforce__pear'))).toBe(true) + expect(reads.some((path) => path.includes('hoopsheet') || path.includes('citrus'))).toBe(false) + }) + + it('reads each probe PR record once when the same PR is mounted under both pull roots', async () => { + // `githubPullRoots` lists a repository twice — the nested canonical layout + // and the flat by-id alias — and relayfile-adapters writes the alias as the + // canonical bytes verbatim. Before the dedupe the union of both roots read + // the same pull request twice under two path spellings. + const mount = new FakeMountClient({ + [issuePath(703)]: issueFile(703), + '/github/repos/AgentWorkforce/pear/pulls/703__ar-703-work/meta.json': prFile(703, { + title: 'AR-703 work', + body: '', + head_ref: 'factory/ar-703-work', + state: 'OPEN', + }), + '/github/repos/AgentWorkforce__pear/pulls/by-id/703.json': prFile(703, { + title: 'AR-703 work', + body: '', + head_ref: 'factory/ar-703-work', + state: 'OPEN', + }), + }) + const fleet = new FakeFleetClient() + const factory = createFactory(config(), { + mount, + fleet, + triage: new StaticTriage(), + linear: probeLinearWriteback, + probeCloser: async (input) => ({ repo: input.repo, prNumber: input.prNumber, state: 'CLOSED' }), + }) + + await factory.dispatch(await factory.triageIssue(parseLinearIssue(issuePath(703), issueFile(703)))) + fleet.emitAgentExit('ar-703-impl-pear', 'issue-done') + await flush() + + // One pull request, one read — not one read per path spelling. + expect(probePrRecordReads(mount)).toHaveLength(1) + // The resolution itself is unchanged: PR 703 is still the answer. + expect(factory.status().counters.mergeGateSyntheticClosed).toBe(1) + }) + + it('serves a repeated probe PR resolution for one issue from cache without re-reading the mount', async () => { + // A single completion resolves the same issue's PR more than once + // (`#issueHasCompletionPr`, then `#closeSyntheticProbeIfPresent`) under one + // cache key. The mount branch is the common hit and used to return without + // ever writing the cache it reads, so every one of those calls repeated the + // whole tree walk. The clock never advances here, so both calls are inside + // the TTL and the second must cost ZERO additional mount reads. + const clock = new ManualClock() + const mount = new FakeMountClient({ + [issuePath(704)]: issueFile(704), + '/github/repos/AgentWorkforce__pear/pulls/by-id/704.json': prFile(704, { + title: 'AR-704 work', + body: '', + head_ref: 'factory/ar-704-work', + state: 'OPEN', + }), + '/github/repos/AgentWorkforce__pear/pulls/by-id/9704.json': prFile(9704, { + title: 'Unrelated work', + body: '', + head_ref: 'unrelated-9704', + state: 'OPEN', + }), + }) + const fleet = new FakeFleetClient() + const factory = createFactory(config(), { + mount, + fleet, + triage: new StaticTriage(), + clock, + linear: probeLinearWriteback, + probeCloser: async (input) => ({ repo: input.repo, prNumber: input.prNumber, state: 'CLOSED' }), + }) + + await factory.dispatch(await factory.triageIssue(parseLinearIssue(issuePath(704), issueFile(704)))) + fleet.emitAgentExit('ar-704-impl-pear', 'issue-done') + await flush() + + // Two PRs on the mount, each read exactly once across the whole completion — + // one walk, not one walk per probe call. + expect(probePrRecordReads(mount)).toHaveLength(2) + expect(factory.status().counters.probePrMountReads).toBe(2) + expect(factory.status().counters.mergeGateSyntheticClosed).toBe(1) + }) + it('does not treat a factory label as a synthetic probe marker', async () => { const labelOnlyIssue = realIssueFile(19, ready, { title: 'Label-scoped probe-shaped issue', diff --git a/src/orchestrator/factory.ts b/src/orchestrator/factory.ts index c24055f..18a3b64 100644 --- a/src/orchestrator/factory.ts +++ b/src/orchestrator/factory.ts @@ -806,6 +806,10 @@ export class FactoryLoop implements Factory { // owner/repo#number identity. GitHub-native records outrank Linear mirrors. readonly #dependencyIssues = new Map() readonly #terminalDependencyIdentities = new Set() + /** Sweep-scoped memo of `#dependencyIsTerminalOrMerged`'s mount walk, including + * the negative answer that `#terminalDependencyIdentities` cannot hold. Cleared + * with it at the top of every sweep. */ + readonly #dependencyPrProbes = new Map() readonly #dependencyParkNotices = new Map() #dependencyGithubPathsByIdentity?: Map #dependencyLinearTreeLoaded = false @@ -1197,7 +1201,8 @@ export class FactoryLoop implements Factory { this.#customProbePrResolver = Boolean(ports.probePrResolver) this.#hasProbePrGhRunner = Boolean(ports.probePrGhRunner) this.#probePrGhRunner = ports.probePrGhRunner ?? failClosedGhRunner - this.#probePrResolver = ports.probePrResolver ?? ((issue) => this.#resolveIssuePr(issue)) + this.#probePrResolver = ports.probePrResolver ?? + ((issue) => this.#resolveIssuePr(issue, { repo: this.#probeRepoForIssue(issue) })) this.#logger = normalizeLogger(ports.logger ?? console) this.#clock = ports.clock ?? realClock this.#fleetControlPlane = new FleetControlPlaneCircuit({ @@ -2983,6 +2988,7 @@ export class FactoryLoop implements Factory { } return this.#resolveIssuePr(issue, { titleMarker: FACTORY_E2E_MARKER, + repo: this.#probeRepoForIssue(issue), }) } @@ -2993,9 +2999,29 @@ export class FactoryLoop implements Factory { return this.#resolveIssuePr(issue, { titleMarker: FACTORY_E2E_MARKER, openOnly: true, + repo: this.#probeRepoForIssue(issue), }) } + /** + * Which repository a probe walk may scope itself to. + * + * `resolveIssuePrFromMount` has always accepted `opts.repo`, but + * `#resolveIssuePr` had no way to express one, so every probe crawled the PR + * tree of EVERY configured repository — 21 of them in the live workspace — to + * find a PR that can only ever live in one. This is the same routing answer + * `#dependencyIsTerminalOrMerged` already uses for its own probe, so the two + * probes now scope identically. + * + * `undefined` means the routing is genuinely ambiguous (a decision spanning + * several routes, an issue whose labels match no single repo). The walk then + * stays unscoped, exactly as before: narrowing on a guess would silently fail + * to find a PR that is really there, which is worse than a slow walk. + */ + #probeRepoForIssue(issue: LinearIssue): string | undefined { + return dependencyRepoForIssue(issue, undefined, this.#config) + } + async #resolveIssuePr( issue: LinearIssue, opts: { @@ -3004,6 +3030,7 @@ export class FactoryLoop implements Factory { openOnly?: boolean failOnLookupError?: boolean allowLegacyGithubBranch?: boolean + repo?: string } = {}, ): Promise { const issueKey = issueStateKey(issueRef(issue)) @@ -3020,8 +3047,21 @@ export class FactoryLoop implements Factory { issue, opts, (prefix) => this.#listRelayfileTree(prefix, 'PR probe resolution'), + this.#probeMountWalkProgress('[factory] PR probe mount read progress', issue), ) if (mountPr) { + // The mount branch runs first and is the common hit, and until now it was + // the one branch that never wrote the cache it reads at the top of this + // method. The cache had a reader and no writer on the hot path, so the + // full tree walk repeated for every caller, on every sweep, forever. + // + // Cached on the same terms as the gh branch below — same key, same TTL, + // same draft exclusion — because the reason to keep a draft uncached is a + // property of the PR (its state is about to flip and the caller wants to + // see that promptly), not of which resolver observed it. + if (!mountPr.draft) { + this.#probePrResolvedCache.set(key, { pr: mountPr, expiresAtMs: now + PROBE_PR_GH_BACKOFF_MS }) + } return mountPr } @@ -3562,6 +3602,7 @@ export class FactoryLoop implements Factory { // current provider snapshots (or merged PR metadata) so a reopened issue // cannot remain permanently resolved after an earlier close event. this.#terminalDependencyIdentities.clear() + this.#dependencyPrProbes.clear() this.#dependencyGithubPathsByIdentity = undefined this.#dependencyLinearTreeLoaded = false const issueSource = await this.#issueSource() @@ -4706,6 +4747,7 @@ export class FactoryLoop implements Factory { openOnly: true, failOnLookupError: true, allowLegacyGithubBranch: true, + repo: this.#probeRepoForIssue(issue), }) } @@ -5145,6 +5187,52 @@ export class FactoryLoop implements Factory { return Math.max(0, this.#clock.now() - startedAtMs) } + /** + * Progress reporting for the mount PR walk. + * + * `listTree` inside that walk is wrapped by `#listRelayfileTree` — named, + * timed and logged. The `readFile` per candidate path was not: it ran inside a + * bare try/catch that swallows failures into `undefined`, with no logger, no + * counter and no progress line. A walk of several thousand paths at ~175ms + * each therefore emitted its last log line at the final `listTree` and then + * went silent for twelve minutes, which is indistinguishable from a hung + * process. Three investigation layers could not tell those apart from the logs + * alone, so the missing instrumentation is a defect in its own right and not a + * nice-to-have. + * + * Same cadence helper the ready-issue read loop uses, so a long PR probe reads + * like a long issue read; the counter carries the same signal into /evidence. + */ + #probeMountWalkProgress(message: string, issue: LinearIssue): ProbeMountWalkObserver { + const startedAtMs = this.#clock.now() + let lastLoggedAtMs = startedAtMs + return { + onRead: (progress) => { + this.#increment('probePrMountReads') + lastLoggedAtMs = this.#logTimedProgress(message, startedAtMs, lastLoggedAtMs, { + issue: issue.key, + read: progress.read, + total: progress.total, + path: progress.path, + }) + }, + // One line per repository saying why the tree walk was necessary. The walk + // is a permanent silent fallback today, and a silent permanent fallback is + // indistinguishable from a fast path that is working. This makes the day + // the index becomes usable (relayfile-adapters#271) show up in the logs + // instead of passing unnoticed. + onIndexFallback: (repo, reason) => { + this.#increment('probePrIndexFallbacks') + this.#increment(PROBE_PR_INDEX_FALLBACK_COUNTERS[reason]) + this.#logger.debug?.('[factory] PR probe fell back to a full mount walk', { + issue: issue.key, + repo, + reason, + }) + }, + } + } + #logTimedProgress( message: string, startedAtMs: number, @@ -9174,6 +9262,16 @@ export class FactoryLoop implements Factory { if (!issue) return false const repo = dependencyRepoForIssue(issue, undefined, this.#config) if (!repo) return false + // This probe does NOT go through `#resolveIssuePr` — it must not fall back to + // gh — so it never saw that method's cache, and `#terminalDependencyIdentities` + // only ever memoises the TRUE answer. A dependency that is not merged was + // therefore re-walked in full for every issue declaring it, on every sweep; + // several issues blocked on one dependency multiplied a single tree walk by + // the number of blocked issues. Memoise the negative answer too, on exactly + // the lifetime of the terminal set beside it: cleared at the top of each + // sweep, so a PR that merges between sweeps is still observed. + const memoized = this.#dependencyPrProbes.get(identity) + if (memoized !== undefined) return memoized const pullRequest = await resolveIssuePrFromMount( this.#mount, this.#config, @@ -9183,8 +9281,12 @@ export class FactoryLoop implements Factory { repo, }, (prefix) => this.#listRelayfileTree(prefix, 'dependency PR probe resolution'), + this.#probeMountWalkProgress('[factory] dependency PR probe mount read progress', issue), ) - if (normalizePrState(pullRequest?.state) !== 'MERGED') return false + if (normalizePrState(pullRequest?.state) !== 'MERGED') { + this.#dependencyPrProbes.set(identity, false) + return false + } this.#terminalDependencyIdentities.add(identity) return true } @@ -15910,8 +16012,25 @@ export class FactoryLoop implements Factory { settleIssueWritebackOnce() this.#completionInFlight.delete(completionKey) const stateKey = issueStateKey(record.issue) - this.#probePrGhBackoffUntilMs.delete(stateKey) - this.#probePrResolvedCache.delete(stateKey) + // Both maps are keyed by issue state key PLUS the option suffixes + // `#resolveIssuePr` appends (`:open`, `:legacy`, `:open:legacy`), but this + // invalidation only ever deleted the bare key. Every `openOnly` probe — + // `#openPrForIssue` and `#openCompletionPr`, i.e. the completion path — was + // therefore never invalidated at all. That was survivable only because the + // mount branch never wrote the cache; now that it does, a stale OPEN entry + // outliving completion would be a live correctness bug, so clear the whole + // family. Suffixes always start with ':', and no other issue's state key can + // be this one followed by ':', so the prefix test cannot over-delete. + for (const cacheKey of [...this.#probePrResolvedCache.keys()]) { + if (cacheKey === stateKey || cacheKey.startsWith(`${stateKey}:`)) { + this.#probePrResolvedCache.delete(cacheKey) + } + } + for (const backoffKey of [...this.#probePrGhBackoffUntilMs.keys()]) { + if (backoffKey === stateKey || backoffKey.startsWith(`${stateKey}:`)) { + this.#probePrGhBackoffUntilMs.delete(backoffKey) + } + } // Cancellation must see the subscription identity so it can issue the // idempotent Relayfile DELETE before clearing the local owner maps. await this.#cancelBabysittersForIssue(record.issue) @@ -18911,6 +19030,7 @@ export class FactoryLoop implements Factory { ? await this.#probePrResolver(issue) : await this.#resolveIssuePr(issue, { titleMarker: FACTORY_E2E_MARKER, + repo: this.#probeRepoForIssue(issue), }) if (!probe) { return @@ -20411,6 +20531,83 @@ const linearIssueMirrorsGithubIssue = (issue: LinearIssue, ghIssue: GithubIssueS .some((line) => line.trim() === `${GITHUB_MIRROR_SOURCE_PREFIX}${ghIssue.url}`) } +/** + * Why this walk could not be answered from `pulls/_index.json`. + * + * `index-absent` — no index file at the canonical path. + * `index-shape-unrecognised` — an index exists but is not the documented bare + * array of rows. The eager backfill writer + * (relayfile-adapters `lazy.ts`) wraps it as + * `{ pulls: [...] }`, while the incremental + * index emitter writes the bare array, so the + * shape depends on which writer last touched it. + * `index-without-head-ref` — a readable index, but its rows carry no + * `headRef`. This is the normal case today and + * it is why the walk cannot be short-circuited: + * the primary match (score 30) is a branch-name + * match, and a row without `headRef` cannot rule + * out a branch match on any other pull request. + * `index-usable` — rows carry `headRef`; the walk is now avoidable + * and this resolver should be taught the fast path. + */ +type PullIndexFallbackReason = + | 'index-absent' + | 'index-shape-unrecognised' + | 'index-without-head-ref' + | 'index-usable' + +const PROBE_PR_INDEX_FALLBACK_COUNTERS: Record = { + 'index-absent': 'probePrIndexAbsent', + 'index-shape-unrecognised': 'probePrIndexShapeUnrecognised', + 'index-without-head-ref': 'probePrIndexWithoutHeadRef', + // Not a fallback condition so much as a standing invitation: rows carry + // `headRef`, so the walk is now avoidable and this counter going non-zero is + // the cue to build the fast path. + 'index-usable': 'probePrIndexUsableButUnused', +} + +type ProbeMountWalkObserver = { + onRead?: (progress: { read: number; total: number; path: string }) => void + onIndexFallback?: (repo: string, reason: PullIndexFallbackReason) => void +} + +/** + * Classify the pull index without acting on it. + * + * Deliberately diagnostic only. Factory's issue-side reader + * (`#githubIssuePathsFromIndex`) uses its index as a NARROWING FILTER over + * paths it still reads individually, which is safe because it can only + * over-select. A pull index cannot be used that way today: it carries no + * `headRef`, so it cannot exclude any pull request from a branch match, and a + * title hit alone (score 20) must never be returned as the answer while an + * unread branch match (score 30) could outrank it. Until the row contract + * carries `headRef` (relayfile-adapters#271), the only honest thing to do with + * the index is say out loud why it did not help. + */ +const classifyPullIndexFallback = async ( + mount: MountClient, + repo: string, +): Promise => { + const [owner, name] = repo.split('/') + if (!owner || !name) return 'index-absent' + let parsed: unknown + try { + const { content } = await mount.readFile(`${GITHUB_ISSUE_ROOT}/${owner}/${name}/pulls/_index.json`) + parsed = parseJsonContent(content) + } catch (error) { + // A mount that is failing pass-wide must not be reported as "no index" — + // that is the same convention the tree reads below already follow. + if (isPassWideRelayfileFault(error)) throw error + return 'index-absent' + } + if (!Array.isArray(parsed)) return 'index-shape-unrecognised' + // An empty index proves nothing about the row contract, so it must not read + // as usable — `[].every(...)` is vacuously true. + return parsed.length > 0 && parsed.every((entry) => typeof asRecord(entry)?.headRef === 'string') + ? 'index-usable' + : 'index-without-head-ref' +} + const resolveIssuePrFromMount = async ( mount: MountClient, config: FactoryConfig, @@ -20424,10 +20621,14 @@ const resolveIssuePrFromMount = async ( repo?: string } = {}, listTree: (prefix: string) => Promise = (prefix) => mount.listTree(prefix), + observer: ProbeMountWalkObserver = {}, ): Promise => { const candidates: Array = [] const listErrors: unknown[] = [] for (const repo of opts.repo ? [opts.repo] : reposFromConfig(config)) { + if (observer.onIndexFallback) { + observer.onIndexFallback(repo, await classifyPullIndexFallback(mount, repo)) + } const paths = new Set() for (const root of githubPullRoots(repo)) { try { @@ -20437,9 +20638,41 @@ const resolveIssuePrFromMount = async ( listErrors.push(error) } } + + // `githubPullRoots` is plural, and both of its roots describe the SAME + // repository: the nested `//pulls/` layout and the flat + // `__/pulls/by-id/` one. A pull request is generally present + // under both, spelled differently, so the union walked most PRs twice — in + // the live workspace 2877 nested paths plus 1156 by-id paths for roughly + // 1156 actual pull requests. + // + // Collapse them on the identity the PATH already carries. `githubPullPathParts` + // reads owner/repo/number out of either spelling and costs no mount read, so + // the dedupe is free. Insertion order is preserved and the first spelling + // encountered wins, which is the same candidate the existing stable sort kept + // when two spellings of one PR tied — so the winner does not move. + // + // Paths the matcher does not recognise (`pulls/_index.json`, per-PR + // `comments/*.json`) carry no PR identity, so they are left in the walk and + // still read exactly as before rather than being filtered on a guess. + const walk: string[] = [] + const seenPulls = new Set() for (const path of paths) { if (!path.endsWith('.json')) continue + const parts = githubPullPathParts(path) + if (parts) { + const identity = `${parts.owner}/${parts.repo}#${parts.number}`.toLowerCase() + if (seenPulls.has(identity)) continue + seenPulls.add(identity) + } + walk.push(path) + } + + let read = 0 + for (const path of walk) { const pr = await readProbePrCandidate(mount, path) + read += 1 + observer.onRead?.({ read, total: walk.length, path }) if (opts.openOnly && normalizePrState(pr?.state) !== 'OPEN') continue const score = pr ? issuePrMatchScore(pr, issue, opts.titleMarker ?? config.safety.requireTitlePrefix, opts)