Skip to content

Commit 57a0968

Browse files
committed
merge(dev): sync lidge-jun#810 onto tip before full-review verdict
2 parents 6d3990e + 33caf33 commit 57a0968

6 files changed

Lines changed: 197 additions & 48 deletions

File tree

devlog/_plan/260731_pr_issue_triage_round/050_windows_ci_flake_rca.md

Lines changed: 65 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -192,3 +192,68 @@ macOS의 claude 핑 테스트도 같은 계열이다. 90ms 침묵에 25ms 핑
192192

193193
두 문서를 합치지 않고 나란히 둔다. 이 문서는 **이 라운드에서 무엇을 고쳤는지**
194194
기록이고, 그 문서는 **모드 분류와 개선 후보**의 조사다. 목적이 다르다.
195+
196+
## 마지막 라운드 — 남은 세 건과 정책화
197+
198+
`000_research.md`의 개선 후보 5번(예산 정책화)을 실행했다. 그 전에 남은 실패 세 건을
199+
각각 확인했는데, **셋 다 원인이 달랐다.**
200+
201+
### 1. server-auth 루프 테스트 — 내가 한 번 놓쳤다
202+
203+
이전 라운드에서 하니스 4개짜리 하나를 고쳤는데, 같은 파일에 **5개짜리와 6개짜리가
204+
더 있었다.** `startPoolRetryHarness()`는 호출마다 `TEST_DIR`를 지우고 다시 만들고,
205+
서버를 띄우고, 전역 `fetch`를 리다이렉트한다. 그걸 다섯 번 하면 5초 안에 안 끝난다.
206+
207+
둘 다 body 커서를 쓰는 단일 하니스로 바꿨다. 각 케이스는 여전히 자기 원본 400과
208+
`acct-pool-a` 단일 dispatch를 증명한다.
209+
210+
### 2. WS-REBIND-01 — 예산 초과가 아니었다
211+
212+
748ms에 죽었다. 5초 예산에 748ms면 타임아웃이 아니다. 테스트 안에 **자체 1초 데드라인**
213+
있었다:
214+
215+
```
216+
setTimeout(() => reject(new Error("websocket retry timed out")), 1_000);
217+
```
218+
219+
실제 서버를 멈췄다 다시 띄우고, WebSocket을 열고, 계정 간 2홉 재시도를 기다리는 데
220+
1초다. 부하 걸린 러너에서는 낙관적이다.
221+
222+
**내부 데드라인이 테스트 예산보다 짧으면 타임아웃보다 빨리 죽어서 로직 에러처럼 보인다.**
223+
이게 이 건이 유독 무작위처럼 보였던 이유다. 헬퍼에 `INTERNAL_DEADLINE_MS`로 이름을 붙였다.
224+
225+
덤으로 하니스가 **WebSocket 레지스트리를 안 지운다**는 것도 찾았다. 프로세스 전역이고
226+
teardown에서 살아남는데, WS-REBIND-01은 계정별 정확한 소켓 개수를 단언한다. 다섯 가지
227+
상태를 지우면서 이것만 빠져 있었다.
228+
229+
다만 **로컬에서 재현은 못 했다.** 리셋을 빼고 돌려도, 소켓을 하나 흘려놓고 돌려도
230+
통과했다. 그래서 커밋에 "방어적 조치이고 재현된 수정이 아니다"라고 적었다. 재현 못 한 걸
231+
고쳤다고 쓰면 다음 사람이 잘못된 근거 위에서 판단한다.
232+
233+
### 3. executeArchivedCleanup — 우리 문제가 아니다
234+
235+
**이미 20초를 받고 25052ms에 죽었다.** 20초를 넘기는 테스트는 예산 문제가 아니라는
236+
신호라 먼저 재봤다.
237+
238+
```
239+
(pass) executeArchivedCleanup > permanent cleanup removes logs, goals, and memory rows … [7.16ms]
240+
```
241+
242+
로컬 **7.16ms**, CI **25052ms**. 3500배 차이다. sleep도 spawn도 없는 동기 SQLite
243+
작업이다. 테스트가 느린 게 아니라 러너가 그 순간 그만큼 느렸다는 뜻이다.
244+
245+
숫자를 다시 올리는 대신 `STORE_BUDGET_MS`로 묶었다. 이 파일에만 흩어진 리터럴이
246+
22개였다.
247+
248+
## 정책 — `tests/helpers/test-budget.ts`
249+
250+
예산을 올린 커밋이 네 개가 되도록 매번 숫자를 따로 정하고 있었다. 스위트 전체에
251+
timeout 리터럴이 52개다. 정당한 예산과 침묵당한 플레이크를 구분할 방법이 없다.
252+
253+
헬퍼는 **숫자가 아니라 규칙**을 적는다. 둘 다 참일 때만 예산을 올릴 수 있다:
254+
255+
1. 그 기다림이 테스트가 단언하는 것에 본질적이다.
256+
2. **ablation이 여전히 실패한다.**
257+
258+
1번만 있고 2번이 없으면 무력한 테스트를 고정시키는 것이다. `020`에서 지적한 바로 그
259+
실패 모드다.

tests/codex-app-server-processes.test.ts

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -359,16 +359,23 @@ describe("Windows Win32_Process owner enumeration (#476)", () => {
359359
[
360360
"-NoProfile", "-NoLogo", "-NonInteractive", "-WindowStyle", "Hidden",
361361
"-Command",
362-
"Start-Sleep -Seconds 25 # codex app-server integration-probe",
362+
"Start-Sleep -Seconds 45 # codex app-server integration-probe",
363363
],
364364
{ stdio: "ignore", windowsHide: true },
365365
);
366366
try {
367367
expect(child.pid).toBeGreaterThan(1);
368-
// Brief settle so Win32_Process can observe the child.
369-
Atomics.wait(new Int32Array(new SharedArrayBuffer(4)), 0, 0, 250);
370-
const snapshots = listWindowsSnapshots();
371-
const match = snapshots.find(snapshot => snapshot.pid === child.pid);
368+
// Brief settle so Win32_Process can observe the child. A loaded Windows
369+
// runner can also exhaust one CIM enumeration deadline, so tolerate one
370+
// transient empty result while keeping the production timeout unchanged.
371+
Bun.sleepSync(250);
372+
let snapshots = listWindowsSnapshots();
373+
let match = snapshots.find(snapshot => snapshot.pid === child.pid);
374+
if (!match) {
375+
Bun.sleepSync(250);
376+
snapshots = listWindowsSnapshots();
377+
match = snapshots.find(snapshot => snapshot.pid === child.pid);
378+
}
372379
expect(match).toBeDefined();
373380
expect(match!.owner).toMatch(/\\/);
374381
expect(match!.commandLine.toLowerCase()).toContain("codex app-server");
@@ -381,6 +388,6 @@ describe("Windows Win32_Process owner enumeration (#476)", () => {
381388
}
382389
}
383390
},
384-
{ timeout: 30_000 },
391+
{ timeout: 35_000 },
385392
);
386393
});

tests/helpers/test-budget.ts

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,50 @@
1+
/**
2+
* Test budgets for work that is genuinely slow, not for making red go away.
3+
*
4+
* Bun's default is 5s. That is generous for a pure function and thin for anything
5+
* that spawns a process, binds a server, or writes SQLite on a loaded CI runner —
6+
* which is why a run of windows-latest failures kept blaming a different test each
7+
* time. The blame moved; the cause did not.
8+
*
9+
* ## When you may raise a budget
10+
*
11+
* Both must hold:
12+
*
13+
* 1. **The wait is intrinsic to the assertion.** The tray socket-inheritance test
14+
* launches PowerShell, which launches Bun, then rebinds the port to prove the
15+
* child never inherited the listen socket. Those processes ARE the proof, so it
16+
* gets a budget. The sidebar route tests spawned `gh` only incidentally while
17+
* claiming route reachability, so they got the spawn DELETED instead. Ask which
18+
* kind you have before reaching for a number.
19+
* 2. **The ablation still fails.** Revert the production behaviour the test covers
20+
* and confirm the test goes red. A budget that hides a vacuous test is worse than
21+
* the flake, because it converts a reliability signal into silence.
22+
*
23+
* If only (1) holds, you have not finished. If neither holds, delete the wait.
24+
*
25+
* ## Why these numbers
26+
*
27+
* They are headroom against runner contention, not measured durations. Local timings
28+
* are typically two to four orders of magnitude smaller: the storage cleanup test
29+
* that blew a 20s CI budget runs in ~7ms here. Sizing to the local number is what
30+
* produced the original 5s failures.
31+
*/
32+
33+
/** Real child process: PowerShell, a CLI smoke test, an external binary. */
34+
export const SPAWN_BUDGET_MS = 45_000;
35+
36+
/** Binds a real server or opens a real socket, including restart-and-reconnect flows. */
37+
export const SERVER_BUDGET_MS = 30_000;
38+
39+
/** Touches SQLite or the filesystem repeatedly. Slow on Windows for reasons outside our code. */
40+
export const STORE_BUDGET_MS = 30_000;
41+
42+
/**
43+
* A deadline *inside* a test, for an await that would otherwise hang forever.
44+
*
45+
* Keep these at least a few times under the surrounding budget. An internal deadline
46+
* shorter than the test budget fails faster than a timeout and reads as a logic error:
47+
* WS-REBIND-01 died at 748ms against its own hardcoded 1s while the budget was 5s, and
48+
* that mismatch is exactly why it looked random rather than slow.
49+
*/
50+
export const INTERNAL_DEADLINE_MS = 15_000;

tests/server-auth.test.ts

Lines changed: 43 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,8 @@ import { request as httpRequest } from "node:http";
55
import { tmpdir } from "node:os";
66
import { join } from "node:path";
77
import { saveCodexAccountCredential } from "../src/codex/account-store";
8-
import { getTrackedCodexWebSocketCountForAccount } from "../src/codex/websocket-registry";
8+
import { clearCodexWebSocketRegistry, getTrackedCodexWebSocketCountForAccount } from "../src/codex/websocket-registry";
9+
import { INTERNAL_DEADLINE_MS, SERVER_BUDGET_MS } from "./helpers/test-budget";
910
import { clearAccountNeedsReauth, clearAccountQuota, getAccountQuota, isAccountNeedsReauth, markAccountNeedsReauth, updateAccountQuota } from "../src/codex/auth-api";
1011
import {
1112
CODEX_THREAD_AFFINITY_IDLE_TTL_MS,
@@ -162,6 +163,12 @@ async function startPoolRetryHarness(
162163
clearAccountQuota();
163164
clearAccountNeedsReauth("pool-a");
164165
clearAccountNeedsReauth("pool-b");
166+
// The registry is process-global and survives a harness teardown. WS-REBIND-01
167+
// asserts exact per-account socket counts, so a socket leaked by any earlier test
168+
// in this file shifts its snapshots and fails it in milliseconds — which reads as
169+
// a flake next to the timeouts, but is ordinary shared state. Reset it with the
170+
// rest rather than leaving one of six kinds of state uncleaned.
171+
clearCodexWebSocketRegistry();
165172

166173
const dispatches: string[] = [];
167174
const upstream = Bun.serve({
@@ -1288,7 +1295,7 @@ describe("server local API auth", () => {
12881295
if (globalThis.fetch === matrixFetch) globalThis.fetch = originalGlobalFetch;
12891296
await upstream.stop(true);
12901297
}
1291-
}, { timeout: 30_000 });
1298+
}, { timeout: SERVER_BUDGET_MS });
12921299

12931300
test("internal web-search and vision never forward a non-ChatGPT bearer as Direct sidecar auth", async () => {
12941301
if (existsSync(TEST_DIR)) rmSync(TEST_DIR, { recursive: true });
@@ -1984,15 +1991,18 @@ describe("server local API auth", () => {
19841991
`${exact} suffix`,
19851992
exact.replace("ChatGPT account.", "ChatGPT account"),
19861993
];
1987-
for (const detail of cases) {
1988-
const body = JSON.stringify({ detail });
1989-
const harness = await startPoolRetryHarness(() => rejectionResponse(body));
1990-
try {
1991-
await expectOriginal400(await harness.request(), body);
1992-
expect(harness.dispatches).toEqual(["acct-pool-a"]);
1993-
} finally {
1994-
await stopPoolRetryHarness(harness);
1994+
const negativeBodies = cases.map(detail => JSON.stringify({ detail }));
1995+
let nextNegative = 0;
1996+
const negative = await startPoolRetryHarness(() => rejectionResponse(negativeBodies[nextNegative++]!));
1997+
try {
1998+
for (const body of negativeBodies) {
1999+
const priorDispatches = negative.dispatches.length;
2000+
await expectOriginal400(await negative.request(), body);
2001+
expect(negative.dispatches.slice(priorDispatches)).toEqual(["acct-pool-a"]);
19952002
}
2003+
expect(nextNegative).toBe(negativeBodies.length);
2004+
} finally {
2005+
await stopPoolRetryHarness(negative);
19962006
}
19972007
const positive = await startPoolRetryHarness(accountId => accountId === "acct-pool-a"
19982008
? rejectionResponse(JSON.stringify({ detail: ` THE '${POOL_RETRY_MODEL}' MODEL IS NOT SUPPORTED\nWHEN USING CODEX WITH A CHATGPT ACCOUNT. ` }))
@@ -2006,14 +2016,23 @@ describe("server local API auth", () => {
20062016
}, 12_000);
20072017

20082018
test("valid JSON wrong top-level shape never authorizes a pool retry", async () => {
2009-
for (const body of ['"string"', "42", "true", "null", '["detail"]']) {
2010-
const harness = await startPoolRetryHarness(() => rejectionResponse(body));
2011-
try {
2019+
// One harness, five bodies — same reason as the sibling above. Each
2020+
// startPoolRetryHarness() wipes and recreates TEST_DIR, binds a server, and
2021+
// redirects global fetch; five of those did not fit Bun's 5s default on a
2022+
// Windows runner, and the request still in flight when the budget expired
2023+
// raced the next test through that same global fetch.
2024+
const bodies = ['"string"', "42", "true", "null", '["detail"]'];
2025+
let nextBody = 0;
2026+
const harness = await startPoolRetryHarness(() => rejectionResponse(bodies[nextBody++]!));
2027+
try {
2028+
for (const body of bodies) {
2029+
const priorDispatches = harness.dispatches.length;
20122030
await expectOriginal400(await harness.request(), body);
2013-
expect(harness.dispatches).toEqual(["acct-pool-a"]);
2014-
} finally {
2015-
await stopPoolRetryHarness(harness);
2031+
expect(harness.dispatches.slice(priorDispatches)).toEqual(["acct-pool-a"]);
20162032
}
2033+
expect(nextBody).toBe(bodies.length);
2034+
} finally {
2035+
await stopPoolRetryHarness(harness);
20172036
}
20182037
});
20192038

@@ -2085,7 +2104,13 @@ describe("server local API auth", () => {
20852104
if (String(event.data).includes("response.completed")) resolve();
20862105
});
20872106
ws.addEventListener("error", () => reject(new Error("websocket retry failed")), { once: true });
2088-
setTimeout(() => reject(new Error("websocket retry timed out")), 1_000);
2107+
// This 1s was the real cause of WS-REBIND-01 failing at 748ms on windows-latest:
2108+
// an internal deadline, not Bun's test budget, which is why it died far too fast
2109+
// to look like a timeout. The test stops and restarts a real server, opens a real
2110+
// WebSocket, and waits for a two-hop retry across accounts — a second of that on a
2111+
// contended runner is optimistic. The assertions below are unchanged; only the
2112+
// room to reach them grew.
2113+
setTimeout(() => reject(new Error("websocket retry timed out")), INTERNAL_DEADLINE_MS);
20892114
});
20902115
expect(harness.dispatches).toEqual(["acct-pool-a", "acct-pool-b"]);
20912116
expect(registrySnapshots).toEqual([[1, 0], [0, 1]]);
@@ -2095,7 +2120,7 @@ describe("server local API auth", () => {
20952120
ws.close();
20962121
await stopPoolRetryHarness(harness);
20972122
}
2098-
});
2123+
}, { timeout: 30_000 });
20992124

21002125
test("passthrough connect failure records selected pool account health", async () => {
21012126
if (existsSync(TEST_DIR)) rmSync(TEST_DIR, { recursive: true });

0 commit comments

Comments
 (0)