[Bug]: four tests exceed their timeouts in the unsharded macOS control lane, first observed once the lane was able to finish

[lidge-jun]

Client or integration

CI only; not a client-facing path.

Area

CI and release

Summary

Four tests exceed their own timeouts when the full suite runs unsharded in the macos control lane. They are not new failures. They have never been reachable, because that lane has a 30-minute job budget and the suite needs about fifty minutes, so every run has been cancelled slightly past the halfway point for months and these four sit beyond it.

An authorized one-off measurement raised only the control job budget to 60 minutes on a throwaway branch and let the lane finish for the first time. Test step 23:13:17Z to 00:03:56Z, 50m39s wall, Bun reporting 3034.18s. Result: 26475 pass, 46 skip, 5 fail across 26526 tests in 1343 files. The suite exited 1 on its own rather than being killed, so this is a complete run.

One of the five failures is the measurement itself and is expected: tests/ci-workflows/ci-workflows.test.ts:121 pins the control budget at 30 and the branch set it to 60. That guard is working. The other four are the subject of this issue:

Test	Observed	Bound
web-search heartbeat retry	6233.05ms	5000ms
image non-droppable	60323.51ms	60000ms
imageTierBias	91516.75ms	60000ms
provider-option ownership spine	31801.03ms	30000ms

Three are marginal and one overshoots by half again, which is usually the spread that separates a budget sized on a quiet machine from a genuine stall. They need individual dispositions and none should be resolved by raising a bound before someone has explained where the time goes. tests/helpers/test-budget.ts states the two conditions a budget increase has to meet, and they apply here.

Worth noting why this lane is worth keeping rather than sharding away: it is the only place the suite runs in one process, so it is the only oracle for shared-process and cross-file ordering pressure. These four results are the first thing it has ever told us.

The 30-minute budget itself is #4905. This issue is the four tests, not the budget.

Reproduction

Not reproducible locally and no local verification was attempted. It requires the unsharded control lane to run to completion, which currently requires a job budget larger than the one in ci.yml.

Version

2.59.0 (dev), measured against base 61ee64747bedc5fafbeb5fc811898ea4db4ec738.

Operating system

macOS, GitHub-hosted runner.

Provider and model

Not provider-specific.

Logs or error output

26475 pass
46 skip
5 fail
383039 expect() calls
Ran 26526 tests across 1343 files. [3034.18s]

Screenshots and supporting files

Not applicable.

Redacted configuration

Not applicable.

[lidge-jun]

리뷰 · 우선순위 64 / 80

이 이슈는 unsharded macos control 레인이 처음으로 끝까지 갔을 때 드러난, 테스트 자체 timeout 네 건입니다. tip(e80e571f63, package 2.59.0)의 .github/workflows/ci.yml macos-control은 job timeout-minutes: 30(#4905)이고, Test 스텝은 bun test --isolate --timeout 60000 tests입니다. 레인 기본 per-test 천장 60초와, 테스트가 직접 적은 더 짧은 bound가 섞여 있습니다. 본문의 60분 측정은 예산만 잠깐 올린 one-off이고, 이 이슈의 대상은 job 예산이 아니라 그 네 테스트입니다.

tip에서 이름을 대조하면 대략 이렇게 대응됩니다. (1) tests/web-search/web-search.test.ts의 “retry wait longer than the stall budget still succeeds (heartbeats feed the watchdog)” — 명시 5_000, 관측 6233ms. (2) tests/adapters/anthropic/anthropic-image-normalize.test.ts N1 “oversized-dimension PNG … not dropped” — 파일에 per-test timeout 없음 → 레인 60s, 관측 60323ms. (3) tests/adapters/anthropic/anthropic-image-retry.test.ts imageTierBias 플럼빙 — 역시 명시 timeout 없음 → 60s, 관측 91516ms로 bound를 크게 초과. (4) tests/adapters/openai/openai-provider-option-e2e.test.ts “keeps Pool, Direct, and API ownership stable…” — 명시 30_000, 관측 31801ms. 세 건은 경계 근처, imageTierBias 한 건은 절반 이상 넘깁니다.

측정 숫자도 맥락이 있습니다. 스위트 wall 약 50m39s, Bun 3034s, 26475 pass / 5 fail 중 하나는 ci-workflows가 control budget 30을 핀하는 가드가 60으로 바뀐 측정 자체입니다. 가드가 일을 한 것이고, 남은 네 건만 disposition 대상입니다. 로컬 재현은 본문대로 불가에 가깝고, 계측 PR도 호스티드 macos-control(또는 동등 unsharded)에서 돌려야 의미가 있습니다.

tests/helpers/test-budget.ts 정책은 예산을 올리려면 (1) 대기가 주장 자체에 Intrinsic하고 (2) 동작을 제거해도 테스트가 여전히 실패해야 한다고 못 박습니다. 네 건 모두에 맹목 timeout/--timeout 상향은 금지에 가깝습니다. 특히 N1·imageTierBias는 실제 Bun.Image 리사이즈/인코드가 있어 경합 민감하지만, 어디에 시간이 갔는지(인코드 호출 수, 캐시, 동시성, 픽스처 크기) 설명이 없습니다. ownership spine은 프로세스·ACL·관리 API를 한 덩어리로 도는 통합이라 30s가 타이트할 수는 있으나, 역시 ablation·구간 계측 없이 숫자만 키우면 안 됩니다.

레인을 유지할 이유는 본문과 같습니다. 단일 프로세스 전체 스위트 오라클이라 shared-process·교차 파일 순서 압력을 샤드가 못 봅니다. #4905 job 30분과 이 네 건은 분리해서 추적하는 편이 맞습니다. types/config 스플릿과 무관합니다.

점수는 중상입니다. 신호는 진짜이고 재현 조건이 문서화돼 있지만, 운영자 대면 버그가 아니라 CI 신뢰성·예산 규율 이슈입니다. 다음 액션은 per-test disposition 네 장입니다.

tests/web-search/web-search.test.ts:1218 - heartbeat retry, bound 5s. 1.5s backoff+stall 1s 설계상 여유 부족 가능. 구간 타이밍 후 소폭 상향 또는 인위 대기 축소.
tests/adapters/anthropic/anthropic-image-normalize.test.ts (N1 not dropped) - 레인 60s에 60.3s. Bun.Image 경로 계측 없이 budget 올리지 말 것.
tests/adapters/anthropic/anthropic-image-retry.test.ts (imageTierBias) - 60s에 91s. 가장 수상. 인코드/리사이즈 hang·중복 작업 여부 먼저.
tests/adapters/openai/openai-provider-option-e2e.test.ts:123 - ownership spine 30s에 31.8s. 단계별 elapsed 로그 후 SERVER/SPAWN 예산 정책과 照合.
tests/helpers/test-budget.ts - 예산 상향 두 조건. 이 이슈의 기본 심판 기준.

메인테이너의 판단이 필요한 지점

• imageTierBias 91s를 성능 결함으로 볼지, 맥 러너 경합으로 볼지.
• macos control job 30분([Bug]: macOS control is cancelled near its 30-minute limit in full dispatch CI #4905)과 테스트 예산 이슈를 계속 분리할지.
• ownership spine을 쪼갤지, 계측 후 정책에 맞는 상수만 조정할지.

너의 추천

job timeout을 올리는 PR은 받지 마세요. 네 테스트마다 (관측 구간 → tip 코드에서 시간 sink → ablation → 그다음에만 budget) 순서로 이슈를 쪼개거나 체크리스트로 닫으세요. imageTierBias부터 보는 게 좋습니다. 라벨은 바꾸지 마세요.

이 댓글은 grok-bot이 작성했습니다

[lidge-jun]

First completed macos control run. Until now this lane had only ever produced cancellations, so there was no measurement to argue from; #5037 was why, and #5048 fixed it.

Run 35318628931, job 105515988406, frozen ref ci/control-probe-2590 at 56a99d3848. Started 07:52:52Z, completed 09:03:27Z.

26822 pass
   56 skip
    4 fail
    1 error
411261 expect() calls
Ran 26882 tests across 1367 files. [4184.63s]

The suite itself took 69m45s, inside the 75-minute budget #5028 gave it, so the budget is right and this issue is the whole remaining gap. The four failures are the four named here, all timeouts, none of them assertions:

test	budget	observed
sideband GET /v1/live/{callId} relays the exact frame ceiling bidirectionally	20000ms	30837ms
shellStreamExec completion acknowledgement > appends structured shellResult and streamClose after the exit event	60000ms	63078ms
openai-chat inline image normalization > imageTierBias from incoming meta reaches the normalizer	60000ms	83040ms
OpenAI provider-option integration spine > keeps Pool, Direct, and API ownership stable across transports and management	30000ms	30029ms

Two things this measurement settles.

It is the same four every time. imageTierBias was recorded at 91516ms when this issue was opened and came in at 83040ms here, so the overrun is large and repeatable rather than marginal — except for the provider-option spine, which missed by 29ms and is a genuine edge case.

And all four pass in macos 1/2 and macos 2/2, which run the same files. The difference is that the control lane loads all 1367 files into one process. Whatever is being measured here is contention in that process, not the behaviour under test, which is why raising these four budgets would be the wrong fix: it would buy green by agreeing to stop noticing.

The lane can now be dispatched and will report. gh workflow run ci.yml --ref dev -f lane=macos-control is enough; the frozen ref is no longer needed.

[lidge-jun]

Third control dispatch: the lane ran out of its 75-minute budget, and the failing set was a different five.

Run 35343636646 (job 105595102031) was dispatched at c5b39d43e6. The Test step started 12:15:49Z and the job was cancelled at 13:31:19Z by timeout-minutes: 75, inside tests/providers/kiro/kiro-usage-quota.test.ts. There is no final tally for this run: it was cut off, not finished.

What it did report before the cut is the part worth recording. Five failures, and not one of them is in the table above, nor in the set from the previous completed control (run 35318628931 at 56a99d3848: 26822 pass / 4 fail / 56 skip, 26882 tests across 1367 files, 4184.63s).

Test	Observed	Failure shape
Codex autostart shim > Unix timeout cleanup preserves EPERM when passive probes keep failing	10059.54ms	own timeout, 10000ms
codex-auth API > pool plan persistence fails closed without waiting behind a busy config writer	5370.79ms	wall-clock assertion, codex-auth-api.test.ts:2379 expected < 2000, received 5350.45
Codex reset-credit recovery coordinator > expires an abort-ignoring revalidation without dispatch	2473.03ms	expiry raced its own dispatch window
connection-reset recovery parity on the web-search legs > the sidecar leg replays a reset on a fresh connection while keeping the provider HTTP version pin	4224.18ms	logged [upstream-retry] connection reset (web-search-loop) — retrying (2/3) before failing
socks5Fetch > closes a keep-alive socket after a fixed-length response completes	294.83ms	expect(...) true/false at tests/lib/socks5-fetch.test.ts:171

The last one is different in kind from everything else this lane has produced. It failed in 294ms against a plain boolean expectation, so it is not a budget overrun at all: it observed the socket before the close had been applied. That race can misfire in a sharded lane too, which the other entries cannot, and it deserves a look on its own terms rather than as another line in a timing table.

Three dispatches have now reached or nearly reached the end of the suite, and each produced a disjoint failing set. The common factor is sensitivity to elapsed time in a single process holding 1367 files, not any one subsystem. That is the argument against fixing any of these by raising a bound: a larger number moves the boundary to a different set of tests without removing the class. The four tests this issue is about passed again in the sharded lanes at the current dev tip f02f3613be, where the aggregate is ci: success.

A separate fact about the lane itself, recorded here because it changes how much this evidence is worth rather than what it means. 4184.63s is 69.7 minutes of test execution alone; adding checkout, dependency install, and the GUI build puts the job at its 75-minute bound, which is exactly where it stopped. I am not proposing a bump. Widening it buys one more run of the same shape and pushes back the point at which a genuine hang becomes visible, which is the reason the comment in ci.yml gives for choosing 75 in the first place. If this lane is to stay usable as release evidence, the thing to change is the tests that assert on wall-clock duration, so the result stops depending on how loaded the machine is.

Dev tip state at the time of writing, for whoever picks this up: f02f3613be is green on every sharded leg, GUI locale parity is clean across all nine locales against en.ts (2818 keys), and the file-size ratchet has no offenders with 37 of 51 entries sitting exactly at their cap.

[lidge-jun]

The sideband test in this table is not confined to the unsharded control lane. It failed in the ordinary sharded macos 2/2 leg on dev at ecd3adae75, run 35363697700, at 15318.60ms against its own 15000ms bound:

(fail) sideband GET /v1/live/{callId} relays the exact frame ceiling bidirectionally [15318.60ms]
error: sideband timeout
  at tests/server/server-live.test.ts:662:49

That matters for how this issue is read. The framing so far has been that the unsharded pool is a special pressure environment and these four are what it surfaces. This occurrence had none of that: one of four macOS shards, the same budget, 318 milliseconds over. The bound is simply close enough to the work that ordinary runner variance crosses it.

It also means the disposition cannot be "these pass in the sharded lanes, so only the control lane needs attention". A test that overshoots by two percent will fail somewhere on a schedule nobody controls, and each occurrence costs a rerun and an investigation that reaches this same conclusion.

Recorded, not fixed here, because the 2.59.0 candidate was already frozen at ecd3adae75 when this fired and the fix belongs to the test rather than to the release.

[lidge-jun]

A fourth control dispatch, and a fourth disjoint failing set. Run 35386429688 on codex/4997-phase-timing-evidence reported:

tests/providers/cursor/cursor-stream-health.test.ts:227
  error: Cursor stream stalled: no inbound frames for 5s before turnEnded
tests/server/server-auth.test.ts:4264
  the native passthrough reset fixture escaping as an unhandled error (#5073)

Neither is in the table above, and neither was in the sets from the three earlier dispatches. Four runs have now produced four failing sets with no overlap between them, which is about as clear as this kind of evidence gets: the failing test is selected by load, not by subsystem.

The Cursor one is worth naming separately because it is a new shape. It is not a test budget being exceeded — it is production code declaring a stall. src/adapters/cursor/live-transport.ts fails the turn when no inbound frame arrives for five seconds, and under control-lane contention the fixture's own frames do not arrive inside that window. A five-second inbound-frame expectation is a reasonable production contract and an unreasonable thing to assert against a synthetic server sharing a process with 1367 test files.

The instrumentation that answers "which phase grew" landed on dev as 7817cd57f7 (#5081). It splits preparation, the measured execution and teardown-plus-reap, and an open phase emits progress ticks reporting whether the case's own counter moved, so a truncated record ending in moving=yes is slow execution and one ending in moving=no is a stall. Those were indistinguishable before: both looked like a log that stops mid-phase.

The disposition PR is #5082, now rebased onto dev. It moves confirmed preparation cost out of the measured window for the image and provider-option cases and does not touch any budget.

[lidge-jun]

Disposition for the fifth failure on this lane, which is a different class from the four in the table above.

tests/providers/cursor/cursor-stream-health.test.ts fails with Cursor stream stalled: no inbound frames for 5s before turnEnded, raised from src/adapters/cursor/live-transport.ts. It is not a test exceeding its own budget. It is production code declaring a stall: the T04 watchdog fails a turn whose inbound frames stop arriving, and under control-lane contention the fixture's own frames do not arrive inside the window.

Three things are worth separating here.

The five seconds is not the production contract. CURSOR_STREAM_SILENCE_FAIL_MS is 30s. The case injects isolationBudgetMs(1_000), which tests/helpers/ci-watchdog.ts floors at 5s on a non-Windows CI runner, and the stall message prints that injected budget back. So the number in the failure is the test's own scaled knob.

The scaling is what makes this worse rather than better. The case asserts that no deadline expires while meaningful frames keep arriving, and it demonstrates that by observing progress for three times the silence budget. At a 5s floor that is a demand for 15 consecutive seconds during which no 5s gap in frame decoding occurs, inside a 22s fixture window. Raising the floor lengthens the exposure. The budget was already scaled once for this same case in #3940; there is no value of it that makes a "no deadline expired" assertion safe on a runner that can pause for more than ten seconds.

So this one should not be resolved by a budget at all. #5131 adds a T04-only clock seam — now, setTimeout, clearTimeout on CursorTransportFactoryInput, defaulting to the globals, in the shape StageLeaseClock already uses in src/cli/account-api.ts — and rewrites the case to advance virtual time by hand between frames whose arrival it awaits. Contention can then delay a frame without any deadline passing. Production budgets, the first-frame timer, the turn-ended grace and the outbound heartbeat are untouched, and the firing half of the contract stays on real timers in three cases that assert a stall does happen, which a slow runner cannot turn red for being slow.

One limitation worth recording against this issue: the lane that produced this failure still cannot finish inside its 30-minute budget (#4905), so hosted CI on that PR cannot demonstrate the failure disappearing. The argument is structural rather than empirical — the assertion no longer contains a term for elapsed real time.

No local suite was run for any of this; the analysis is static plus the run log quoted in this issue.

[lidge-jun]

Disposition for the Cursor case recorded on this issue earlier: fixed on dev by #5131.

It was never a test exceeding its own budget. src/adapters/cursor/live-transport.ts fails the turn when no inbound frame arrives inside CURSOR_STREAM_SILENCE_FAIL_MS, and under control-lane contention the fixture's own frames did not arrive inside the window the test had configured. A five-second inbound-frame expectation is a defensible production contract and an indefensible thing to assert against a synthetic in-process server sharing a runtime with 1367 test files.

The production timeouts are unchanged — 30s silence, 90s heartbeat-only. What changed is that the T04 watchdog now reads time and schedules its one timer through an injectable clock that defaults to the globals, so the test advances a virtual one-second silence by hand instead of waiting for a real one. Nothing else about the transport's timers moves with it, and the elapsedMs diagnostic deliberately stays on the wall clock because turnStartedAt is stamped there and the pair has to subtract coherently.

That is the same shape as #5082, which replaced a host service-manager probe with a seam rather than relaxing anything. Four of these cases are now dispositioned by removing a dependency on the machine keeping up, not by giving the machine more time.