diff --git a/devlog/_plan/260905_windows_suite_stabilization/000_plan.md b/devlog/_plan/260905_windows_suite_stabilization/000_plan.md index 306805f50d..984f6449ba 100644 --- a/devlog/_plan/260905_windows_suite_stabilization/000_plan.md +++ b/devlog/_plan/260905_windows_suite_stabilization/000_plan.md @@ -73,6 +73,15 @@ prevent a defect that does not exist. ## Acceptance for the unit 1. Four shards, pinned runtime, **0 fail, twice consecutively**, with logs. + + Status: CI run 33926041666 (`cfc8de963`) — all four Windows shards green, + 4462/4628/4305/4413 pass. Second run 33928082123 on the rebased head + (`dc09663cb`): every file this unit touches green again, but windows 2/4 + red on three cases that arrived on `dev` via #3533 between the two runs + (`060`). The stack's own scope is met twice; the suite-wide bar is not, + and `070` is the next work-phase for that drift. + + Published as #3548 → #3549 → #3550 against `dev`. 2. Every fix is a root-cause change: no assertion weakened, no timeout inflated without naming the intrinsic operation it covers. 3. macOS unchanged for every touched file, verified by running it. diff --git a/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md b/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md index ba8949a975..2c66ae7c89 100644 --- a/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md +++ b/devlog/_plan/260905_windows_suite_stabilization/050_ci_residual_retained_root.md @@ -270,3 +270,52 @@ case reaps cleanly. process, no unhandled ENOENT. 3. CI re-dispatch: windows 2/4 SUCCESS with **no** "killed N dangling processes" line in the log, and every case in this file under its budget with margin. + +--- + +## Third CI round: all four Windows shards green + +Run 33926041666 (head `cfc8de963`): + +| shard | pass | fail | dangling | +|---|---|---|---| +| 1/4 | 4462 | **0** | 0 | +| 2/4 | 4628 | **0** | 0 | +| 3/4 | 4305 | **0** | — | +| 4/4 | 4413 | **0** | — | + +The file that failed twice, on the same hosted runner class: + +``` +(pass) startup and CLI sync-cache … owns K [8459.45ms] (was 18743 / 15536 timeout) +(pass) native restore … owns K [2935.56ms] +(pass) POST /api/sync … newer convergence catalog [7303.73ms] (was 20140 timeout) +(pass) POST /api/sync … newer retained catalog [9908.46ms] +(pass) a persisted runtime selection … [1772.21ms] +(pass) two processes at the post-approval seam … [3383.29ms] +``` + +Every case is under `SPAWN_BUDGET_MS` with 4-5× margin, and this run happened +to be a fast one (8.5 s where the previous run took 18.7 s for the same case). +That spread — 8.5 to 18.7 s for identical work — is the thing the 15 s and 20 s +budgets could never absorb, and it is why the class fix mattered more than the +first case fix. + +### What was actually wrong, in one paragraph + +Not the product. Not the lock. The file's per-case budgets were sized from a +~450 ms local run for work that costs 8-19 s on the hosted Windows runner, and +its harness had no reap-before-delete ordering, so any budget miss produced a +dangling child plus a follow-on ENOENT/unhandled-rejection that obscured the +real message. Three commits: a budget on one case (moved the failure), then the +class budget + child registration + a detached barrier race (fixed it). + +### Verification ledger for the barrier fix + +The unhandled-rejection claim was checked by a probe, not by reading: insert a +5 s sleep after the barrier under a 3 s budget. Original code reports the +timeout **plus** `Unhandled error between tests: sync exited before provider +barrier (143)`; fixed code reports the timeout alone. Two earlier attempts at +the fix (resolve-to-Error, catch-in-finally) still produced the unhandled error +under that probe and were discarded before commit. The probe was removed and the +file is 6/6 on macOS. diff --git a/devlog/_plan/260905_windows_suite_stabilization/060_dev_drift_atime.md b/devlog/_plan/260905_windows_suite_stabilization/060_dev_drift_atime.md new file mode 100644 index 0000000000..c313fc7142 --- /dev/null +++ b/devlog/_plan/260905_windows_suite_stabilization/060_dev_drift_atime.md @@ -0,0 +1,82 @@ +# 060 — wp4: dev moved under the stack — the quorum-cache atime observer on Windows + +Research doc. Found by the second confirmation run, which happened to be the first +run after rebasing the stack onto current `dev` (`d6b457462`, 36 commits ahead of +the original base). + +## The run + +Run 33928082123 (head `dc09663cb`, rebased): windows 1/4, 3/4, 4/4 SUCCESS; +2/4 FAILURE with three new cases: + +``` +(fail) Anthropic failover quorum cache > removing an account invalidates immediately, not after the TTL +(fail) Anthropic failover quorum cache > a rotation invalidates immediately rather than waiting out the TTL +(fail) Anthropic failover quorum cache > a manual account selection invalidates immediately + at tests/routing/anthropic-quorum-cache.test.ts:154:28 + expect(storeWasRead()).toBe(true) Expected: true Received: false +``` + +Everything this stack touches passed on the same run: `keep-native-v1` 12/12, +the six `retained-root-serialization` cases, `update-notify` with its skip. + +## Provenance + +`tests/routing/anthropic-quorum-cache.test.ts` reached `dev` today through +#3523 → #3526 → #3530 → #3533 (merged 21:44Z). None of those commits exist on +the pre-rebase stack, and the run before the rebase (33926041666) was all green. +So this is drift under the stack, not a regression the stack introduced. + +## Mechanism, from reading — NOT yet measured + +The test observes whether `loadAuthStore` hit the file by pinning `auth.json`'s +**atime** 60 s into the past and checking whether it moved: + +```ts +function markStoreUnread(): void { + utimesSync(storePath(), new Date(Date.now() - 60_000), stats.mtime); +} +function storeWasRead(): boolean { + return statSync(storePath()).atimeMs > Date.now() - 30_000; +} +``` + +On Windows, NTFS last-access-time updates are **disabled by default** on +client SKUs since Windows 7 (`NtfsDisableLastAccessUpdate`), and on newer +builds they are "system managed" — updated only when the volume is small or +at most once per hour. A `readFileSync` does not move atime there. So the +three cases that assert "the store WAS read" cannot see the read, while the +cases that assert "was NOT read" pass vacuously on the same platform. + +That is a hypothesis with a strong prior (it is a well-known NTFS default) +and it explains the exact split — three "invalidates immediately" cases red, +the "shares one read" and "holds no credential material" cases green. But +this unit has been wrong from reading before (`007`), so it is not a +diagnosis until the atime behaviour is measured on the runner. + +## Why it is a separate work-phase + +- It is not in this stack's write set and not caused by it. +- The fix belongs to the test's author's design: observing a syscall through + atime is the thing that does not port, and the replacement (an injected + reader counter, or a `readFileSync` spy) is a design choice in a file this + stack has never touched. +- The stack's own acceptance — the three defects it set out to fix — is met on + every surface. Holding #3548-#3550 hostage to a defect that landed on `dev` + after they were planned would be the wrong coupling. + +## Next + +A new work-phase, dependency-ordered after this stack lands or independently +as a fourth PR against `dev`: + +1. Measure: on windows-latest, does `readFileSync` move `atimeMs` at all? + A ten-line probe in a scratch `--eval`. +2. If not: replace the atime observer with a direct one (a counting wrapper + around the store reader injected for the test), keeping every assertion. +3. `fuck-powershell` case: `ntfs-atime-disabled-by-default` if (1) confirms. + +Until then, `c-1` ("0 fail twice consecutively") is met for the stack's own +scope at runs 33926041666 and — for the three files it changes — 33928082123, +but NOT for the suite as a whole, because `dev` now carries a Windows failure +of its own. diff --git a/devlog/_plan/260905_windows_suite_stabilization/070_quorum_cache_observer.md b/devlog/_plan/260905_windows_suite_stabilization/070_quorum_cache_observer.md new file mode 100644 index 0000000000..eda175ab5a --- /dev/null +++ b/devlog/_plan/260905_windows_suite_stabilization/070_quorum_cache_observer.md @@ -0,0 +1,193 @@ +# 070 — wp4: the quorum-cache test observes file reads through atime, which NTFS does not update + +Implementation phase. Independent of the three landed fixes (disjoint write set: +one test file). Three failures on windows 2/4, present on `dev` since #3533. + +## Measured, not read + +A scratch step on `windows-latest` (run 33929916059, keyring windows job), the +exact operation the test performs: + +``` +$ fsutil behavior query DisableLastAccess +DisableLastAccess = 3 (System Managed, Last Access Time Updates DISABLED) + +PROBE {"before":1788564769875,"after":1788564769875,"moved":false,"storeWasRead":false} +``` + +`readFileSync` does not move `atimeMs` on the hosted Windows runner. The +hypothesis in `060` is confirmed on the platform where the failure occurs. + +## What the test does + +`tests/routing/anthropic-quorum-cache.test.ts:70-77`: + +```ts +function markStoreUnread(): void { + utimesSync(storePath(), new Date(Date.now() - 60_000), stats.mtime); // pin atime into the past +} +function storeWasRead(): boolean { + return statSync(storePath()).atimeMs > Date.now() - 30_000; // did it move? +} +``` + +Four of the seven cases use this observer (`:87`, `:112`, `:154`, `:166`). The three that assert `storeWasRead() === true` +("rotation / removal / manual selection invalidate immediately") fail on +Windows because the read leaves atime where `utimesSync` put it. The one that +asserts `false` ("a burst shares one read") passes there **vacuously** — it +would pass even if the cache were broken and read the file 25 times, which is +the worse of the two outcomes: a green test that cannot fail. + +The comment on the observer says why it was chosen: "without stubbing the +module … a direct observation of the syscall this cache exists to avoid." That +is a good instinct on POSIX. On NTFS the syscall leaves no trace to observe. + +## Fix: observe the syscall with a path-filtered spy — no `src/` change + +An earlier draft added a guarded read counter to `src/oauth/store.ts`. The audit +rejected it, correctly: the guard only stops production from READING the +counter, the increment itself still executes on every production store read, +and that is process-global test instrumentation inside a credential module. +The repository already observes filesystem calls from tests without touching +`src/` — `tests/claude-integration/claude-system-env-auto.test.ts:76` spies on +`node:fs` `readFileSync`. The same instrument, filtered to the one path that +matters, is the observation the atime trick was reaching for. + +What the spy has to see: `hasAnthropicFailoverQuorum` → `getAccountSet` → +`loadAuthStoreInternal` → `readFileSync(auth.json)` (`src/oauth/store.ts:344`). +The refresh-intent reads at `:166`/`:177`, the lock snapshot at `:404` and +`peekAuthStore` at `:383` are other files or other callers and never satisfy +this cache, so the filter must be the exact `auth.json` path — not "any read". + +### MODIFY `tests/routing/anthropic-quorum-cache.test.ts` (the only file) + +```ts +-import { afterEach, beforeEach, describe, expect, test } from "bun:test"; +-import { mkdtempSync, statSync, utimesSync } from "node:fs"; ++import { afterEach, beforeEach, describe, expect, spyOn, test } from "bun:test"; ++import * as fs from "node:fs"; ++import { mkdtempSync } from "node:fs"; + + const originalHome = process.env.OPENCODEX_HOME; + let home: string; ++let readSpy: ReturnType | undefined; ++let authReadsBefore = 0; + ++/** ++ * Count readFileSync calls against THIS home's auth.json. The previous observer pinned ++ * atime and checked whether readFileSync moved it; on windows-latest NTFS last-access ++ * updates are disabled (fsutil DisableLastAccess = 3, measured in run 33929916059), so ++ * the read left atime untouched, the three "invalidates immediately" cases could never ++ * see the read they assert on, and the "shares one read" case passed vacuously. The ++ * spy observes the same syscall where the platform cannot hide it. ++ */ ++function authReadCount(): number { ++ const target = join(home, "auth.json"); ++ return (readSpy?.mock.calls ?? []).filter(([p]) => String(p) === target).length; ++} + + beforeEach(() => { + home = mkdtempSync(join(tmpdir(), "ocx-quorum-cache-")); + process.env.OPENCODEX_HOME = home; ++ readSpy = spyOn(fs, "readFileSync"); // pass-through: no mockImplementation + clearAnthropicAccountPoolState(); + forgetAnthropicFailoverQuorum(); + }); + + afterEach(() => { ++ readSpy?.mockRestore(); ++ readSpy = undefined; + clearAnthropicAccountPoolState(); + … + }); + +-function storePath() … markStoreUnread() … storeWasRead() // atime versions, deleted ++function markStoreUnread(): void { authReadsBefore = authReadCount(); } ++function storeWasRead(): boolean { return authReadCount() > authReadsBefore; } +``` + +Every call site of `markStoreUnread` / `storeWasRead` is unchanged; only the +helpers' bodies move. `spyOn` without `mockImplementation` records calls and +passes through to the real `readFileSync`, so the store behaves exactly as in +production. + +The spy is installed AFTER `mkdtempSync` (which does not read) and restored in +`afterEach` before the sandbox is removed, matching the claude-system-env +pattern. + +## The "one read" oracle, stated precisely + +The burst case's name says "shares one store read", but a cache FILL is not one +read: `hasAnthropicFailoverQuorum` calls `getAccountSet` (one `auth.json` read) +and then `isPoolCredentialUsable` → `getAccountCredential` for up to two +accounts (`src/oauth/anthropic-routing.ts:222,294,300`) — each of which goes +through `loadAuthStore` again. So a fill is one-to-three reads. + +What the case actually proves — and what `markStoreUnread` AFTER the prime +call measures — is **zero additional reads while the cache is warm**. That is +the property that matters (the cache exists to keep reads off the request +path), it is exactly what the original atime version was asserting, and it is +what the spy version asserts. The case name is kept; a one-line comment in the +test says "zero reads during hits, not one read per fill", so nobody later +tightens it to `=== 1` and discovers the fill count the hard way. + +Refactoring the fill to a single read is a product change outside this +unit's scope and is not needed to make the observation honest. + +### MODIFY `tests/routing/anthropic-quorum-cache.test.ts` + +```ts +-import { mkdtempSync, statSync, utimesSync } from "node:fs"; ++import { mkdtempSync } from "node:fs"; +-import { getAccountSet, markAccountNeedsReauth, saveCredential } from "../../src/oauth/store"; ++import { authStoreReadCountForTestsOnly, getAccountSet, markAccountNeedsReauth, saveCredential } from "../../src/oauth/store"; + +-/** Observe the store read without stubbing the module: … atime … */ +-function storePath(): string { … } +-function markStoreUnread(): void { … } +-function storeWasRead(): boolean { … } ++/** ++ * Observe the store read at the store's own seam. An earlier version pinned atime and ++ * checked whether it moved; NTFS on windows-latest has last-access updates disabled ++ * (fsutil DisableLastAccess = 3), so readFileSync left atime untouched and the three ++ * "invalidates immediately" cases could never see the read they assert on — while the ++ * "shares one read" case passed vacuously. Counting loadAuthStoreInternal is the same ++ * observation, made where the platform cannot hide it. ++ */ ++let readsBefore = 0; ++function markStoreUnread(): void { readsBefore = authStoreReadCountForTestsOnly(); } ++function storeWasRead(): boolean { return authStoreReadCountForTestsOnly() > readsBefore; } +``` + +Every call site of `markStoreUnread` / `storeWasRead` is unchanged; only the +two helpers' bodies move. The six assertions keep their exact shape. + +### Why the path filter is not the fragile part + +The earlier draft worried that a filesystem spy "sees every read and has to +filter by path". It does — and the path is `join(home, "auth.json")`, the same +expression the test already used for `storePath()`. An exact-string match on a +path this test itself created is not fragile; it is the most specific +observation available, and it needs no seam in `src/`. + +## Acceptance + +1. **Ablation first, on macOS**: temporarily disable the cache-hit return at + `src/oauth/anthropic-routing.ts:291` (make the `if` condition `false`). The + burst case must go red on `storeWasRead() === false` — proving the spy sees + the reads atime could not. Reverted before commit; `git diff --stat` shows + only the test file. +2. macOS: `bun test tests/routing/anthropic-quorum-cache.test.ts` 7/7. +3. `bun run typecheck` clean. No `src/` change, so `privacy:scan` is untouched. +4. CI dispatch on the stacked head: windows 2/4 SUCCESS, the three cases + green in the log. + +## Stack position + +PR 4 on top of #3550, against `codex/win-3-k-owner-budget`. One test file; no +product source touched, which keeps this unit's record intact. + +## Corpus + +New `fuck-powershell` case `ntfs-atime-disabled-by-default` with the +`fsutil` output and the probe as its repro. diff --git a/tests/routing/anthropic-quorum-cache.test.ts b/tests/routing/anthropic-quorum-cache.test.ts index 2d609c0875..401961cff6 100644 --- a/tests/routing/anthropic-quorum-cache.test.ts +++ b/tests/routing/anthropic-quorum-cache.test.ts @@ -12,8 +12,9 @@ * still visible once it expires, and a rotation invalidates immediately rather than answering the * next question from a pre-failure count. */ -import { afterEach, beforeEach, describe, expect, test } from "bun:test"; -import { mkdtempSync, statSync, utimesSync } from "node:fs"; +import { afterEach, beforeEach, describe, expect, spyOn, test } from "bun:test"; +import * as fs from "node:fs"; +import { mkdtempSync } from "node:fs"; import { tmpdir } from "node:os"; import { join } from "node:path"; import { @@ -29,15 +30,21 @@ import { removeTreeWithRetry } from "../helpers/remove-tree"; const originalHome = process.env.OPENCODEX_HOME; let home: string; +let readSpy: ReturnType | undefined; +let authReadsBefore = 0; beforeEach(() => { home = mkdtempSync(join(tmpdir(), "ocx-quorum-cache-")); process.env.OPENCODEX_HOME = home; + // Pass-through spy (no mockImplementation): records calls, the real read still happens. + readSpy = spyOn(fs, "readFileSync"); clearAnthropicAccountPoolState(); forgetAnthropicFailoverQuorum(); }); afterEach(() => { + readSpy?.mockRestore(); + readSpy = undefined; clearAnthropicAccountPoolState(); forgetAnthropicFailoverQuorum(); if (originalHome === undefined) delete process.env.OPENCODEX_HOME; @@ -59,28 +66,37 @@ async function seed(count: number, offset = 0): Promise { } /** - * Observe the store read without stubbing the module: `loadAuthStore` calls `readFileSync`, - * which updates atime. Pinning atime into the past and checking whether it moved is a direct - * observation of the syscall this cache exists to avoid. + * Observe the store read without stubbing the module: count `readFileSync` calls against + * THIS home's auth.json — the syscall this cache exists to avoid. + * + * The previous observer pinned atime into the past and checked whether the read moved it. + * On windows-latest NTFS last-access updates are disabled (fsutil DisableLastAccess = 3, + * measured in run 33929916059), so `readFileSync` left atime untouched: the three + * "invalidates immediately" cases could never see the read they assert on, and the + * "shares one read" case passed vacuously. The spy sees the same syscall where the + * platform cannot hide it. The path filter keeps refresh-intent files, lock snapshots and + * `peekAuthStore` out of the count; only the hardened store read can satisfy the cache. */ -function storePath(): string { - return join(home, "auth.json"); +function authReadCount(): number { + const target = join(home, "auth.json"); + return (readSpy?.mock.calls ?? []).filter(([path]) => String(path) === target).length; } function markStoreUnread(): void { - const stats = statSync(storePath()); - utimesSync(storePath(), new Date(Date.now() - 60_000), stats.mtime); + authReadsBefore = authReadCount(); } function storeWasRead(): boolean { - return statSync(storePath()).atimeMs > Date.now() - 30_000; + return authReadCount() > authReadsBefore; } describe("Anthropic failover quorum cache", () => { test("a burst of requests inside the TTL window shares one store read", async () => { const start = Date.now(); await seed(2); - // Prime the cache, then prove the next calls do not touch the file at all. + // Prime the cache, then prove the next calls do not touch the file at all. This asserts + // ZERO reads during hits, not one read per fill: a fill is getAccountSet plus up to two + // getAccountCredential calls through isPoolCredentialUsable, each a store read. expect(hasAnthropicFailoverQuorum(start)).toBe(true); markStoreUnread(); for (let i = 0; i < 25; i++) expect(hasAnthropicFailoverQuorum(start + i)).toBe(true);