Skip to content

fix(fabrika-cli): cut the excess-operand CLI suite to 5 spawns and take the network out of it - #4857

Merged
usirin merged 2 commits into
mainfrom
usirin/fabrika-cli-subprocess-suite-cost-4847-ACE52A23
Aug 3, 2026
Merged

fix(fabrika-cli): cut the excess-operand CLI suite to 5 spawns and take the network out of it#4857
usirin merged 2 commits into
mainfrom
usirin/fabrika-cli-subprocess-suite-cost-4847-ACE52A23

Conversation

@usirin

@usirin usirin commented Aug 3, 2026

Copy link
Copy Markdown
Member

A test in packages/fabrika-cli was spawning twelve real subprocesses to check one guard, and one of those subprocesses fetched from GitHub every time it ran. That fetch took 15 seconds on a quiet runner and 41 seconds under merge-queue load, where it blew a 30-second ceiling and ejected an unrelated docs-only PR from the queue. This cuts the file to five spawns, none of which touch the network, and re-sizes the ceiling against what the job actually costs.

PR #4835 is blocked on this landing. It is a docs-only diff that has now been ejected from the merge queue twice by this test, and nothing in its own diff touches packages/fabrika-cli.

The diagnosis, and why the fix is not a bigger number

The issue title frames this as "~15s against a 30s ceiling" — a headroom problem. It is not, and I checked before touching the constant.

fabrika adr resolve — the invocation in the timing-out case — calls loadMerged, which calls fetchAndResolve, which runs a real git fetch --quiet origin main against this repository before it reads anything (packages/fabrika-cli/src/io/git.ts, packages/fabrika-cli/src/adr/base-ref.ts). Measured on one machine:

invocation wall clock
adr next extratoken (no git) 0.71s
adr resolve 0164 0023 (fetches origin/main) 3.29s
adr resolve … from a non-repo cwd 0.38s

That is a network round-trip inside a unit-tier test. It is the part with unbounded variance, it is why one test cost 15.4s of the file's 40.9s green baseline, and it is why the same test cost 41.3s under contention. Raising SUBPROCESS_TEST_TIMEOUT_MS would have left the fetch in place and moved the threshold — the partial mitigation the repo's standing rule says not to ship.

What changed

The variadic case no longer reaches the network. It runs from a scratch directory that is not a git repository, so adr resolve refuses at its first git read. The assertion is not weakened — it is strengthened. The excess-operand check runs at parse time, inside leafCommand's handler wrapper, before the verb reaches git, so a regressed catch-all still prints unexpected operand and seats exit 1 here. The case now also asserts BASE_UNFETCHABLE (3), which positively proves the verb ran rather than merely proving a string was absent; --repo owner/name is what keeps the refusal on 3 instead of the ambiguous 1 the origin-remote lookup returns.

Twelve spawns become five. Each spawn is a cold node+TS load of bin.ts, ~2.3s on CI, so spawn count is the file's cost. Dropped, and where the coverage still lives:

dropped case still covered by
multi-token refusal wording excess-operand.unit.test.tsexcessRefusal(…, ["a","b"])
naming the full verb path folded into the first refusal case (same spawn), plus the unit tier
refusal in a group other than adr excess-operand.unit.test.ts — its coverage guard walks every registered leaf
excess operand following a flag folded into the fixed-arity case, which now passes --dir <dir> extra
root --help and adr --help exit 0 unknown-subcommand.cli.test.ts — asserts this at four depths already

Kept, because only a process proves them: the #4828 repro (exit 1, empty stdout, token and path named), refusal past a fixed arity with nothing written to the scratch dir, variadic absorption, a fixed-arity verb succeeding at its declared arity, and the hidden catch-all staying out of --help.

SUBPROCESS_TEST_TIMEOUT_MS: 30s to 20s, with a comment stating what it is sized for — about 8x the ~2.3s per-spawn CI baseline, against the 2.69x contention factor the issue measured between two runs 24 minutes apart.

Evidence

Local, same machine, before and after:

before after
file test time 5.66s (12 tests) 1.72s (5 tests)
variadic case 1922ms 349ms

The improvement on that case is larger on CI than locally, because the fetch here hits a warm local git over a fast link — 15.4s on the runner versus 1.9s here.

Falsifiability re-proven in both directions, by injecting regressions into excess-operand.ts and reverting:

Neither injected defect can pass this file. pnpm --filter './packages/**' --filter @kampus/infra run test exits 0 (fabrika-cli: 41 files, 554 tests). pnpm typecheck and pnpm lint:worktree clean.

Acceptance criteria

  • Matrix reduced to a representative set, unit-tier-covered cases dropped rather than duplicated — done, 12 to 5.
  • Duration materially below the 40.9s green baseline, evidenced by a run log — local before/after above; this PR's own packages unit tests run is the CI evidence, and its measured file duration gets appended to this body once it reports.
  • Ceiling re-set against the new baseline with headroom exceeding 2.69x, carrying its sizing factor — done, 20s / ~8x, comment cites the factor.
  • The job stays in the merge-queue-gating set and every asserted behaviour is still covered in packages/fabrika-cli/ — done, no workflow change; see the mapping table.
  • pnpm --filter './packages/**' --filter @kampus/infra run test green — done, exit 0.

Fixes #4847

Deviations

1. Declined the in-passing ci.yml comment correction (deferred sibling defect).

2. Narrowed the fix to the one file the issue scopes (sibling left for follow-up).

3. Lowered the ceiling rather than raising it.

  • Said: the AC asks for the ceiling to be re-set against the new baseline with headroom exceeding the 2.69x factor. A reader primed by the issue title might expect a raise.
  • Did: 30s to 20s.
  • Why: with the network gone, the worst case is a single ~2.3s spawn. 20s is ~8x that, well clear of 2.69x, and a lower ceiling makes a genuinely wedged spawn fail inside the job rather than near its budget.
  • Disposition: no action needed; the constant's comment records the sizing.

4. Strengthened the timing-out test's assertion while shrinking the file.

  • Said: the issue asks only that behaviour stay covered.
  • Did: added expect(run.code).toBe(BASE_UNFETCHABLE) to the variadic case, which previously asserted only that a string was absent.
  • Why: a bare not.toContain also passes if the process dies for an unrelated reason. Binding the exit code to the source constant makes "the verb ran and absorbed its operands" the thing actually proven.
  • Disposition: for the reviewer to judge.

Update 2026-08-03 — the CI run log AC 2 asks for

This PR's own packages unit tests job (check run 91636514592, head a77e817) reports:

✓ src/excess-operand.cli.test.ts (5 tests) 13427ms
  Test Files  41 passed (41)
       Tests  554 passed (554)

Against the 40,890ms green baseline recorded in the issue, on the same job: 40.9s -> 13.4s, a 3.05x reduction, with the network fetch gone. That works out to ~2.7s per spawn, which is the figure the new 20s ceiling was sized against — about 7.4x headroom on the slowest single case, clear of the 2.69x contention factor.

usirin added 2 commits August 3, 2026 01:32
…ke the network out of it (#4847)

`excess-operand.cli.test.ts` spawned 12 subprocesses against a 30s per-test
ceiling, and one of them — the variadic case — ran `adr resolve` inside this
repo, where the verb does a real `git fetch origin main` before reading the
base ref. That fetch is the 15.4s green baseline and the 41.3s timeout that
ejected PR #4835 from the merge queue. A bigger ceiling would only have moved
the threshold; the fetch is the cost.

- The variadic case now runs from a scratch directory that is not a git
  repository, so `adr resolve` refuses at its first git read in milliseconds.
  It asserts the same thing plus the exit code, because the excess-operand
  check runs at parse time — before the verb reaches git — so a regressed
  catch-all still seats a usage error here.
- The matrix drops to 5 representative invocations. Message wording and
  cross-group generality are covered in 19ms by `excess-operand.unit.test.ts`;
  help-exits-0 at three depths is covered by `unknown-subcommand.cli.test.ts`.
  What only a subprocess proves — the exit status — is kept, including the
  #4828 repro and the hidden catch-all staying out of `--help`.
- `SUBPROCESS_TEST_TIMEOUT_MS` drops 30s to 20s, sized against the ~2.3s
  per-spawn CI baseline and stated against the 2.69x contention factor the
  issue measured.

Local: 5.66s to 1.72s of test time, variadic case 1922ms to 349ms.
Falsifiability re-proven both ways against injected regressions.
@github-actions

github-actions Bot commented Aug 3, 2026

Copy link
Copy Markdown

No preview deploy

  • No preview deploy for this PR — its diff touches no deploy-relevant path, so no preview stack was minted and e2e is not applicable. (a77e817)
  • web — Stage pr-4857 torn down.

@usirin

usirin commented Aug 3, 2026

Copy link
Copy Markdown
Member Author

review-code: PASS @ a77e817 — merge-ready

Gated fresh against issue #4847. Class: has-code (1 changed file, packages/fabrika-cli/src/excess-operand.cli.test.ts). Required namespaces (class-probe classify --namespaces): review-code — one, and this verdict covers it. §CP re-derived at this head: CONTROL_PLANE_TOUCHED='', GUARD_TOUCHING='', 1 file scanned, 0 .decisions/** content-probed — not blocking-set, so this is a binding marker, not an advisory. .github/** is confirmed untouched; the merge path is unchanged.

Run-evidence bundle: PRESENT for head a77e8179 — producer run 30798115884, artifact 8849830760, manifest.commit == head, schemaVersion 1; checks 2/2 pass; tests 2420/2420 passed, 0 failed, 0 skipped.

Acceptance criteria

  • [PASS] Matrix reduced to a representative set, unit-tier-covered cases dropped rather than duplicated. 12 spawns → 5, counted at the source rather than taken from the report: the base file has 12 fabrika() call sites, the head file has 5 (one per it). Each dropped case verified covered elsewhere, at the file and line:
    • multi-token wording → excess-operand.unit.test.ts:13-17 asserts excessRefusal([…], ["a","b"]) contains unexpected operands "a", "b".
    • naming the full verb path → genuinely folded, not dropped: excess-operand.cli.test.ts:73 asserts for "fabrika adr next" in the surviving first case's same spawn.
    • refusal in a non-adr group → excess-operand.unit.test.ts:28-71, the coverage guard that walks every leaf reachable from registeredGroups and asserts its last declared argument is EXCESS_OPERAND_NAME, with an explicit zero-scope red. Structurally broader than the one eval check spawn it replaces.
    • excess operand following a flag → folded into the fixed-arity case, strengthened: --dir <dir> extra puts the operand after a flag that takes a value, which is the shape a pre-runner argv walk gets wrong, and expect(readdirSync(dir)).toEqual([]) is a new assertion the old case did not make.
    • root --help / adr --help exit 0 → unknown-subcommand.cli.test.ts:71-83, four depths (--help, adr --help, adr next --help, adr next --dir .decisions --help). Claim checked, accurate.
  • [PASS] Duration materially below the 40.9s green baseline, evidenced by a run log. Verified against the job log itself, not the PR body: check run 91636514592 (run 30798115904, head a77e817, conclusion success) contains ✓ src/excess-operand.cli.test.ts (5 tests) 13427ms. 40,890ms → 13,427ms = 3.05×. Same log: Test Files 41 passed (41).
  • [PASS] Ceiling re-set against the new baseline with headroom exceeding 2.69×, carrying its sizing factor. SUBPROCESS_TEST_TIMEOUT_MS = 20_000 at line 28, docblock states the 2.69× factor it was sized against. The number went down and that is the correct direction, on the arithmetic: the CI log gives 13,427ms / 5 spawns = 2,685ms per spawn, and no retained case performs network I/O (proven below), so the worst single case is bounded by one cold spawn. 20s / 2.7s = 7.4×; 2.7s × the measured 2.69× contention factor = 7.3s, well inside 20s. The old ceiling gave 30s / 15.4s = 1.95× — i.e. it sat inside the measured contention band, which is exactly why it ejected docs(release): the release runbook for builders and the release-path pattern doc (#4805) #4835. Headroom improves from 1.95× to ~7.4× while the constant drops. The flake's cause is removed, not relocated.
  • [PASS] Job stays merge-queue-gating and every asserted behaviour stays covered in packages/fabrika-cli/. Diff is exactly one file (pulls/4857/files, +44/−44); no workflow change. The fabrika: a leaf verb silently discards an undeclared extra token and exits 0 #4828 exit-status guard specifically survives as the first retained case (exit 1, unexpected operand "extratoken", for "fabrika adr next", empty stdout) — and it reds against the fabrika: a leaf verb silently discards an undeclared extra token and exits 0 #4828 defect, re-proven below.
  • [PASS] pnpm --filter './packages/**' --filter @kampus/infra run test green. CI packages unit tests = success at this head; bundle reports 2420/2420. Re-run locally in the head worktree: 41 passed (41) files, 554 passed (554) tests.

The coder's three load-bearing claims, independently falsified

1. The git fetch really is on the tested call path — PROVEN, not inferred. Traced the base-shape invocation with GIT_TRACE pointed at a file, so the child's trace was captured rather than swallowed by execCapture. adr resolve 0164 0023 --dir <scratch> run from inside the repo emits, in order:

built-in: git remote get-url origin
built-in: git remote
built-in: git fetch --quiet origin main
built-in: git rev-list --objects --stdin --not --all --quiet --alternate-refs
built-in: git rev-parse --verify --quiet 'origin/main^{commit}'
built-in: git ls-tree --name-only <sha>:<scratch>

The rev-list --objects --stdin --not --all line is the fetch's own negotiation — a real round-trip. The source path is unambiguous: runResolveloadMerged(base, dir) (packages/fabrika-cli/src/adr/base-ref.ts:39-41) → fetchAndResolve(base) (packages/fabrika-cli/src/io/git.ts:85-91), which runs execCapture("git", ["fetch", "--quiet", "origin", "main"]) before anything is read. Critically, the old test's --dir <scratch> does not divert it: --dir only names the directory read at the already-fetched sha. So the issue's "15s vs 30s headroom" framing was wrong and the coder was right to reject it; the remedy is aimed at the real cause.

2. Timings reproduce in ratio. Re-measured on this machine (warm local git, fast link, so absolute numbers differ from the coder's — the ratio is the claim): refusal path adr next extratoken 0.33s (coder: 0.71s); in-repo adr resolve 1.80s (coder: 3.29s); non-repo-cwd adr resolve --repo owner/name 0.36s, exit 3 (coder: 0.38s). ~5× spread between the fetching and non-fetching shapes, reproduced. The 15.4s CI figure is the same effect over a cold runner and a slower link.

3. Falsifiability re-run here, both injections, on the head tree. Not accepted from the report:

  • Catch-all spread first ({[EXCESS_OPERAND_NAME]: …, ...config} in packages/fabrika-cli/src/excess-operand.ts:81): 3 of 5 red, including the variadic case. Worth stating precisely, because it settles the "stronger or weaker?" question: the variadic case failed on line 103's expect(run.code).toBe(BASE_UNFETCHABLE) while line 102's not.toContain("unexpected operand") passed. The pre-PR assertion would have stayed green against this regression. The strengthening is real, not rhetorical.
  • excess.length === 0 guard disarmed (the fabrika: a leaf verb silently discards an undeclared extra token and exits 0 #4828 defect verbatim, excess-operand.ts:72): 2 of 5 red, both refusal cases.
  • Source restored and re-verified green (5 passed) after each injection.

4. CI evidence checked against the run, not the report — see AC 2. All 47 check runs at this head are success or skipped; none failed.

5. PR body intact after the reported blanking. 8,177 chars, all four ## Deviations entries and the dated CI-log update present and coherent. Closing set is exactly {#4847} — a single Fixes #4847, no other closing keyword in the body.

Sub-gates

  • [PASS] comment-discipline — 44 added lines scanned. The added comments are KEEP-category by the deslop-comments rubric: the file docblock records why five spawns and no network (without it the next author re-adds spawns), the SUBPROCESS_TEST_TIMEOUT_MS docblock carries the sizing factor AC 3 explicitly demands, and the three inline notes each explain a deliberate-looking-wrong choice at its site (why the operand trails a value-taking flag; why the non-repo cwd does not weaken the assertion; why help-at-four-depths lives in the sibling file). No narration, no name-restatement, no re-derivation of an ADR.
  • [PASS] deviation-disclosure — four deviations disclosed with said/did/why/disposition, including the two a reader would most want: the ceiling going down rather than up, and .github/** deliberately left untouched (deferred to The packages-tests job header in ci.yml still claims ~7s / ~500 tests; the job runs far longer #4856) to keep this PR off the control-plane merge path while docs(release): the release runbook for builders and the release-path pattern doc (#4805) #4835 waits. Nothing detected that the body does not disclose.
  • unresolved-threads: not applicable — no review threads on this PR.
  • glossary-freshness: not applicable — no new feature folder / public package / export (detector expressible here: 50 candidate surfaces on base).
  • flag-gating: skipped — linked issue carries no **Containment:** marker.
  • session-caching gate: not applicable — 0 candidate lines in the diff.
  • Typecheck clean in the head worktree (@kampus/fabrika-cli tsgo -p tsconfig.json).

Non-blocking observations (no action required for this PR)

Reviewed at head a77e8179542a739d603cdc2f667af3bbd74d5085; head re-resolved before and after posting.

Verdict-written: 2026-08-03T08:54:03Z

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Subprocess test in fabrika-cli runs at ~15s against a 30s ceiling and ejected a PR from the merge queue

1 participant