Skip to content

test(cli): make the unread-reader ceiling a load-independent constant at RUN_TIMEOUT_MS - #14715

Merged
os-sales merged 5 commits into
mainfrom
claude/issue-14648-run-dev-unbuilt-workspace-flake
Sep 3, 2026
Merged

test(cli): make the unread-reader ceiling a load-independent constant at RUN_TIMEOUT_MS#14715
os-sales merged 5 commits into
mainfrom
claude/issue-14648-run-dev-unbuilt-workspace-flake

Conversation

@os-trump

@os-trump os-trump commented Sep 2, 2026

Copy link
Copy Markdown
Collaborator

Fixes #14648

Case 5 of packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts has now ejected the merge queue under two different ceilings. This revision removes the ceiling as a tunable number rather than retuning it a third time.

What the queue proved, and what it did not

The previous revision replaced the fixed UNREAD_HARD_CAP_MS = 40_000 with a per-run derivation. In the queue at 21:50Z it was evicted by its own new assertion:

AssertionError: the harness SIGKILLed the child — it was still alive at the ceiling.
  cap 61464 ms = clamp(40000, 180000, 4 x 7866 ms measured child runtime + 2 x 15000 ms shim bound)

⭐ The diagnostic did its job — it is the only reason there are numbers to read. Calibration came in at 7 866 ms, the ceiling at 61 464 ms, and the child outlived it: more than 7.8x its own calibration, against a FACTOR of 4. The load model is falsified. The diagnosis is not.

Why not "raise FACTOR"

Raising the factor is the same move a third time, and it has the same shape as the constant it replaced. Both previous ceilings were sized comfortably above the worst thing on record when they were written, and both were beaten by a runner that got busier afterwards:

ceiling how it was sized how it died
40_000 constant worst child runtime + the shim's 15 s bound (~22 s measured) went over three times in a day on six-way-sharded queue shards
clamp(40_000, 180_000, 4 x calibration + 2 x bound) a case-1 sample taken minutes earlier on the same runner child outlived the resulting 61 464 ms by more than 7.8x its 7 866 ms sample

A factor picked now would be fitted to the last failure. Nothing on record measures the spread between a calibration and a later run on a shared, six-way-sharded queue runner, so no factor can be justified as enough — only as not beaten yet, which is exactly what the constant it replaced could also say. The derivation's extra term tracks load, and a term that tracks load is a prediction about contention drawn from a sample of the past.

What removes the choice: the property the case pins

This PR's own strongest argument points here, and it holds:

What this case exists to catch is an unbounded wait … Any finite ceiling catches an unbounded wait. The constant was buying false reds, not detection.

The failure this case was written against is a drain wait with no bound armed at all — observed alive at 25 s, 30 s and 60 s, and ending only when something else killed it. Tightening a ceiling buys no detection against that; it buys false reds, and each one here costs a queue rebuild. So the ceiling wants to be the largest value that keeps the failure legible, and it must not track load.

RUN_TIMEOUT_MS is that value, and it is not a new number:

  • past it, the case stops reporting a SIGKILL and starts reporting the beforeAll timeout, which reds all six cases and names none — so it is where legibility ends, not a preference;
  • it is already this file's budget for one child of this suite, and cases 1-4 run the same child. A child here that legitimately needs more than 180 s has broken the whole file, not this case. One number to get wrong instead of two;
  • every load figure on record clears it by an order of magnitude: 23x the 7.9 s calibration, and 3.4x the worst legitimate lifetime yet measured (22.6 s of contended work against 8 competing copies, plus both of the shim's 15 s bounds).

The change

const UNREAD_HARD_CAP_MS = RUN_TIMEOUT_MS;

deriveUnreadCapMs, UNREAD_CAP_RUNTIME_FACTOR, UNREAD_CAP_FLOOR_MS, UNREAD_CAP_CEILING_MS and the mutable unreadCapMs are gone.

The elapsedMs assertion is dropped — it was the only load-sensitive reading left. Against a constant cap it asserts nothing signal === null does not: the harness kills at exactly that cap, so a child that was not killed ran less than it. What it added was a race at the instant a self-exit and the timer coincide. Detection unchanged, one fewer way to red.

The two remaining assertions are about product behaviour and are untouched: the child exits on its own (signal === null), and it exits code === 2.

The measurement is kept as evidence, never as a threshold input. The failure message still carries the cap, this child's lifetime and case 1's calibration, so a triage can still tell a hang from a runner on fire without opening the file. Nothing is skipped, quarantined, relaxed or deleted, and the diagnostic message survives intact.

SHIM_DRAIN_STALL_MS and its parity case stay: the ceiling no longer budgets that bound, but STALL_MS must still sit strictly below it or case 4 stops discriminating, and case 6 reads the closed-reader fast path against it. The docblock is re-anchored to those two surviving consumers rather than to the derivation that is gone.

Verification — final tree cbd95772d0, clean working tree

One file changed, 134 insertions(+), 10 deletions(-). Heavy runs went through scripts/pm/os-verify-lock.sh; verdicts are quoted from its VERDICT line, and no narrowing was needed anywhere — the lock was free on every acquisition (waited 0s).

  • pnpm --filter @objectstack/cli exec vitest run --maxWorkers=2 --reporter=verbose test/run-dev-unbuilt-workspace.e2e.test.ts11 passed (11), 47.54 s. VERDICT command-exit 0 · held the lock 49s.
  • Whole-repo pnpm lint (eslint . --no-inline-config) — VERDICT command-exit 0 · held the lock 61s. Not narrowed.
  • pnpm check:nul-bytes — OK, 8 042 text files scanned, 0 raw control bytes.
  • Gate union on the final tree. node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack, re-derived after merging origin/main because the first derivation reported a stale tree (17 commits behind, 4 gate scripts changed across the range). 27 derived, 27 run, 0 UNRUN per --ran reconciliation. Every exit captured by redirecting to a file first — no pipe touches the status.
  • 2 of the 27 are NOT MEASURED, in the gates' own words — neither a pass nor a red:
    • node scripts/check-test-completeness.mjs (exit 3): "local log to hand it, so the local reading for this gate is NOT MEASURED. ⛔ It is not a red, and there is nothing here to fix."
    • pnpm check:dual-build-cjs-loads (exit 3): "PREREQUISITE NOT MET — this gate reads built output, and some package has no dist/. Run pnpm build first. ⛔ This is NOT a pass: nothing was measured."
  • The package's own typecheck does not cover this filepackages/cli/tsconfig.json has "include": ["src"], so a green pnpm --filter @objectstack/cli typecheck says nothing about a test/ file. Checked explicitly instead: tsc --ignoreConfig --noEmit --strict --module nodenext --moduleResolution nodenext --target es2022 --skipLibCheck --types node test/run-dev-unbuilt-workspace.e2e.test.tsexit 0, and --listFiles confirms the file really is in that program (243 files, the target among them) rather than a green over nothing.

Ablation on the final tree — the hang is still caught

The ceiling is only the instrument; the property is that a real hang reds. Mutation: bin/run-dev.js's if (Date.now() - lastProgressAtfinish(); no-progress branch replaced by one that never finishes.

  • Mutation proven on disk by content before running, anchored at the text meant to change: removed-line count 1 to 0, injected-marker count 0 to 1, blob a4fd1001 to c85ad531.
  • Result: exactly one case red1 failed | 10 passed (11), 207.12 s, VERDICT command-exit 1 — reading the harness SIGKILLed the child — it was still alive at the ceiling. cap 180000 ms (RUN_TIMEOUT_MS, constant and load-independent by design); this child ran 180094 ms; case 1 measured the same child at 4782 ms on this runner minutes earlier. A 38x ratio against the calibration: unambiguously a hang, which is the whole point of keeping the measurement in the message.
  • The parity case and the closed-reader fast-path case correctly stayed green — the mutation left the mirrored constant and the EPIPE path alone.
  • Restore proven by blob identity, git checkout HEAD -- on an absolute path under trap … EXIT INT TERM: blob back to a4fd1001, git diff HEAD empty.
  • No build leg: the child runs this file from source via tsx (const CLI = resolve(HERE, '../bin/run-dev.js')), so no dist/ mediates the spawn path.

⚠️ An ablation of this bound can come back GREEN — recorded in the file

Measured here, and worth more than the pass it interrupted: the first ablation run went green in 31.9 s, and the same mutation on the same tree red at 180 072 ms minutes later. That is not my change and not a flake in the assertion — it is the fixture property the file's own comment already describes: whether the tail finds bytes still pending, and so whether the bound is reached at all, moves with load.

Settled out of band, driving the same child directly (spawn, stderr.pause(), never read), where the pending bytes can actually be counted:

leg child ended elapsed bytes still held at exit
HEAD, unmutated code 2, signal null — exits on its own 19 271 ms 135 408
no-progress branch disabled code null, signal SIGKILL — still alive at the cap 90 019 ms 145 638

So the backpressure is real, the bound is what releases the child, and the mutation does produce a genuine hang. A commit in this PR writes that into the file, because the next person to ablate this bound will otherwise read one green run as "the case does not discriminate" and go looking for the wrong defect.

Scope

Only packages/cli/test/run-dev-unbuilt-workspace.e2e.test.ts is changed. bin/run-dev.js was mutated for the ablation and restored, proven by blob identity. packages/cli/vitest.config.ts and test/vitest-tiers-partition.test.ts belong to #14554 and are untouched here.

The neighbouring closedEnd.elapsedMs < STALL_MS assertion is the same class of oracle on a fully elastic measurement. It has ejected nothing, its margin is roughly twice this one's, and the load-robust rewrite is genuinely arguable rather than mechanical. Left alone deliberately rather than changed on a guess.

No changeset: test-only, publishes nothing from any package. skip-changeset is applied.

Session: https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza


🤖 Generated with Claude Code

Generated by Claude Code

…ad of a constant

`run-dev-unbuilt-workspace.e2e.test.ts` case 5 armed a fixed
`UNREAD_HARD_CAP_MS = 40_000` and asserted the child ended before it. The
constant was derived as "the worst child runtime plus the shim's 15 s bound",
which sums two terms that do not behave alike: the shim's bound is wall clock
and does not move with load, while the child's pre-drain work is elastic and
`bin/run-dev.js` itself records it at 1.0 s idle against 6.9 s contended. The
elastic term's real budget was 25 s, sized against one box, and merge-queue
shards running the full suite six ways sharded went over it.

The ceiling is now derived per run from case 1 — the same argv under the same
`--import` hook, measured on the same runner minutes earlier — clamped between
the constant it replaces and `RUN_TIMEOUT_MS`, and budgeting two of the shim's
bounds rather than one because `run-dev.js` awaits two announcers that can each
pay it. Nothing is skipped, relaxed or removed: all three assertions stand, and
each now carries the derivation so a queue triage can tell a hang from a
ceiling that was too small.

Adds a case holding the mirrored `SHIM_DRAIN_STALL_MS` equal to the shim's own
`STDERR_DRAIN_STALL_MS`, so the derivation cannot be sized around a bound that
moved.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza
@github-actions github-actions Bot added the size/m label Sep 2, 2026
@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

📓 Docs Drift Check

Nothing in this diff resolved to a documentable surface (no symbol, route or SDK anchor derived from 0 changed package(s)), so this run has no opinion about the docs.

What this run could not see
  • a page that states a rule by its inputs shares no identifier with the emitter that implements the rule, so an emitter-only diff cannot list it — not on this run and not on any run. Measured on fix(driver-sql): emit varchar(maxLength) for a text field a declared index keys on #11430: content/docs/protocol/objectql/types.mdx documents the text-family column mapping by the ObjectQL type names it maps FROM (text / textarea / html) while the diff changed createColumn; it went unlisted, and it was the page that diff falsified, in four places. No shared token exists to detect this on, so a rule your change carries has to be re-read by hand in the pages that restate it.

Coarse fallback — 0 page(s) merely mention a changed package (the pre-#9192 predicate, kept for the deliberately-wide backstop): node scripts/docs-audit/affected-docs.mjs --json 4d0d9445a8ed0240e7ca6a393bbe7f4c637e6bd6packageMentionDocs.

@github-actions github-actions Bot added the tests label Sep 2, 2026
@os-trump os-trump added skip-changeset PR has no user-facing published change; bypasses the changeset gate and removed tests labels Sep 2, 2026 — with Claude
@os-trump
os-trump marked this pull request as ready for review September 2, 2026 20:50
@os-trump
os-trump enabled auto-merge September 2, 2026 20:50
@os-trump
os-trump added this pull request to the merge queue Sep 2, 2026
@github-merge-queue
github-merge-queue Bot removed this pull request from the merge queue due to failed status checks Sep 2, 2026
@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

⛔ merge queue 构建失败 — 先分诊,再决定要不要重排

队列构建 33682230163 红了。队列跑的是全量套件(PR 侧 CI 只跑 affected 子集),
所以失败的测试可能在本 PR 没碰过的包里 —— 那不是重排能修的。每次盲目重排都会让排在后面的所有 PR 重建一轮。

失败的 job(日志抽取,best effort):

  • Test Core (1/6) — 失败步骤: Run this shard's tests

    @objectstack/cli:test:  FAIL   integration  test/run-dev-unbuilt-workspace.e2e.test.ts > the mirror direction: a reader that is never coming back > gives up and exits instead of waiting forever
      ↳ 失败原因: @objectstack/cli:test: AssertionError: the harness SIGKILLed the child — it was still alive at the ceiling. cap 61592 ms = clamp(40000, 180000, 4 x 7898 ms measured child runtime + 2 x 15000 ms shim b
    

↳ 失败原因 是判读的关键:超时Test timed out in … / Hook timed out in …)多半是负载/时序,不是本 PR 的回归;
断言AssertionError: …)才指向真实的行为改变。两者的 FAIL 行长得一模一样,只有这一行能区分。

⚠️ 断言这一侧有一类例外,判据是断言在测什么,不是它是不是 AssertionError 断言的对象是产品行为(一个值、一个形状、一次拒收)⇒ 照上面读:真实的行为改变,去查,⛔ 不要重排掉;
断言的对象是这次实验自身的有效性前提(跑完的耗时、负载下的先后、任何只在时间预算内才成立的条件)⇒ 它跟超时是同一类,同样对负载敏感,重排一次是合法的判别手段。
识别是机械的:断言的消息或它比较的值本身点名了一段时长、一个时间戳、一个耗时计数。实测过的一对 —— AssertionError: SecurityPlugin.init() ran: expected false to be true 测的是产品行为(真回归);
AssertionError: this run took over a second, so second-precision stamps could have differed too: expected 1006 to be less than 1000 测的是实验前提:它守护的那条不变式当时是绿的,同一个 head 原样重排一次即成功。
穿着 AssertionError 外衣的时间测量,仍然是时间测量。(⛔ 这只改「怎么读一次红」,不改「哪些测试可以重排」——后者由别处管。)

跨 PR 相同签名(24h,按失败测试文件聚合):

历史信号:

  • 本 PR 过去 24h 无队列失败记录(首次)。
  • 过去 24h 队列共有 21 个失败构建(不含本次)。

分诊清单:

  1. 失败测试在本 PR 改动的包里 → 真回归,修 PR。
  2. 失败测试与本 PR 无关 → 看上面的「跨 PR 相同签名」;已有汇总 issue ⇒ flaky/环境问题实锤,去那张 issue 上谈,修好前重排只会再烧一轮全队列。
  3. 两者都不是 → 可能与同组 PR 语义冲突;等前面的 PR 落地或失败出队后再重排一次即可,不要连续重排。

Generated by Claude Code · merge-queue-triage workflow (#4859)

@os-trump
os-trump added this pull request to the merge queue Sep 2, 2026
@github-merge-queue
github-merge-queue Bot removed this pull request from the merge queue due to failed status checks Sep 2, 2026
@github-actions

github-actions Bot commented Sep 2, 2026

Copy link
Copy Markdown
Contributor

⛔ merge queue 构建失败 — 先分诊,再决定要不要重排

队列构建 33685006566 红了。队列跑的是全量套件(PR 侧 CI 只跑 affected 子集),
所以失败的测试可能在本 PR 没碰过的包里 —— 那不是重排能修的。每次盲目重排都会让排在后面的所有 PR 重建一轮。

失败的 job(日志抽取,best effort):

  • Test Core (1/6) — 失败步骤: Run this shard's tests

    @objectstack/cli:test:  FAIL   integration  test/run-dev-unbuilt-workspace.e2e.test.ts > the mirror direction: a reader that is never coming back > gives up and exits instead of waiting forever
      ↳ 失败原因: @objectstack/cli:test: AssertionError: the harness SIGKILLed the child — it was still alive at the ceiling. cap 61464 ms = clamp(40000, 180000, 4 x 7866 ms measured child runtime + 2 x 15000 ms shim b
    

↳ 失败原因 是判读的关键:超时Test timed out in … / Hook timed out in …)多半是负载/时序,不是本 PR 的回归;
断言AssertionError: …)才指向真实的行为改变。两者的 FAIL 行长得一模一样,只有这一行能区分。

⚠️ 断言这一侧有一类例外,判据是断言在测什么,不是它是不是 AssertionError 断言的对象是产品行为(一个值、一个形状、一次拒收)⇒ 照上面读:真实的行为改变,去查,⛔ 不要重排掉;
断言的对象是这次实验自身的有效性前提(跑完的耗时、负载下的先后、任何只在时间预算内才成立的条件)⇒ 它跟超时是同一类,同样对负载敏感,重排一次是合法的判别手段。
识别是机械的:断言的消息或它比较的值本身点名了一段时长、一个时间戳、一个耗时计数。实测过的一对 —— AssertionError: SecurityPlugin.init() ran: expected false to be true 测的是产品行为(真回归);
AssertionError: this run took over a second, so second-precision stamps could have differed too: expected 1006 to be less than 1000 测的是实验前提:它守护的那条不变式当时是绿的,同一个 head 原样重排一次即成功。
穿着 AssertionError 外衣的时间测量,仍然是时间测量。(⛔ 这只改「怎么读一次红」,不改「哪些测试可以重排」——后者由别处管。)

跨 PR 相同签名(24h,按失败测试文件聚合):

历史信号:

  • ⚠️ 本 PR 过去 24h 已在队列失败 1 次(不含本次)。 内容未变而反复失败 ⇒ 高度怀疑 flaky 测试或与同组 PR 的语义冲突,重排不解决。
  • 过去 24h 队列共有 22 个失败构建(不含本次)。

分诊清单:

  1. 失败测试在本 PR 改动的包里 → 真回归,修 PR。
  2. 失败测试与本 PR 无关 → 看上面的「跨 PR 相同签名」;已有汇总 issue ⇒ flaky/环境问题实锤,去那张 issue 上谈,修好前重排只会再烧一轮全队列。
  3. 两者都不是 → 可能与同组 PR 语义冲突;等前面的 PR 落地或失败出队后再重排一次即可,不要连续重排。

Generated by Claude Code · merge-queue-triage workflow (#4859)

…MEOUT_MS

The derived ceiling was evicted from the merge queue by its own assertion:
`cap 61464 ms = clamp(40000, 180000, 4 x 7866 ms measured child runtime + 2 x
15000 ms shim bound)` — the child outlived a ceiling built from a sample taken
minutes earlier on the same runner by more than 7.8x that sample, against a
FACTOR of 4. That is the second ceiling here beaten by a runner that got busier
after the number was chosen; the first was `UNREAD_HARD_CAP_MS = 40_000`.

Raising the factor would be the same move a third time, and nothing measures
the spread between a calibration and a later run on a six-way-sharded queue
runner, so no factor can be justified as enough — only as not beaten yet.

What removes the choice is the property the case pins. The failure it was
written against is an UNBOUNDED wait, observed alive at 25 s, 30 s and 60 s and
ending only when something killed it, so ANY finite ceiling catches it.
Tightening buys no detection, only false reds. The ceiling therefore wants to
be the largest value that keeps the failure legible and must not track load:
`RUN_TIMEOUT_MS`, past which a SIGKILL is replaced by a `beforeAll` timeout
that reds all six cases and names none. It is already this file's budget for
one child of this suite, so it is one number to get wrong instead of two.

The `elapsedMs < cap` assertion goes with the derivation: against a constant
cap it asserts nothing `signal === null` does not, since the harness kills at
exactly that cap, and it was the only reading here a slower box could move on
its own. The two product assertions stand — the child exits on its own, with
code 2 — and the measurement is kept as evidence in the failure message rather
than as an input to the threshold.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza
…green

Measured twice on one box minutes apart, same tree: disabling the no-progress
branch in `bin/run-dev.js` red case 5 at 180072 ms once, and passed it in
31.9 s the run before. The comment above already explains why — whether the
tail finds bytes still pending moves with load — but it did not say that the
consequence lands on anyone ABLATING the bound, who reads one green run as
"this case does not discriminate" and goes looking for the wrong defect.

Records the out-of-band reading that settles it either way, with the byte
counts: 135408 bytes still held at a clean exit 2 in 19271 ms, against 145638
held by a child still alive at 90 s with the branch disabled.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza
@os-trump os-trump changed the title test(cli): derive the unread-reader ceiling from a measured run instead of a constant test(cli): make the unread-reader ceiling a load-independent constant at RUN_TIMEOUT_MS Sep 2, 2026
Merged via the queue into main with commit accb923 Sep 3, 2026
37 checks passed
@os-sales
os-sales deleted the claude/issue-14648-run-dev-unbuilt-workspace-flake branch September 3, 2026 03:52
os-trump pushed a commit that referenced this pull request Sep 3, 2026
…clock

`run-dev-unbuilt-workspace.e2e.test.ts` case 6 asserted
`closedEnd.elapsedMs < STALL_MS` — a fixed wall-clock bound borrowed from
case 4's parent stall, against a term that is entirely elastic. Tracing what
produces that timing shows the bound was not merely fragile, it was a phantom.

With the read end destroyed, oclif's `displayWarnings()` makes the first
stderr write, the pipe is already gone, node raises `write EPIPE` as an
`error` event on `process.stderr`, nothing is listening, and the child dies
of an uncaught exception at ~1.4 s with exit 1. `writeStderr()` is never
reached, so the bound the case was named after is never armed. Traced with a
`--import` observer: the shim's own 415-byte write is #175 at 9250 ms, behind
174 oclif writes that all EPIPE — 7.8 s after the real child is already dead.

Ablated on `bin/run-dev.js`, same box, same probe (old bound's verdict in
brackets): pristine exit 1 at 1387-1711 ms [green]; write callback removed so
a closed path could only finish on the bound, which is the regression this
case named, exit 1 at 1517-1633 ms [GREEN]; EPIPE made non-fatal, exit 2 at
8787-8979 ms [green, 1.2 s spare]; both, so the path really pays the bound,
exit 2 at 23601-23712 ms [red]. The measurement moved only where the exit
code moved too, and it stayed green on its own regression.

So the exit status is the observation the wall clock was standing in for, and
it carries no load term: 1 means the child died on its first write, 2 means it
reached `handle()`, which is only reachable through `writeStderr()`. This
asserts that directly and keeps the elapsed reading as evidence in the failure
message, the same split #14715 made for case 5.

Exit 1 is what the CLI does rather than what anyone contracted — filed as
#14858, and pinning today's value is what stops that changing silently.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_016yfqQh2dBgPAymYd7xipza
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

size/m skip-changeset PR has no user-facing published change; bypasses the changeset gate tests

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Queue-flake anchor: test/run-dev-unbuilt-workspace.e2e.test.ts

3 participants