Skip to content

Commit 51db9b6

Browse files
Fix test timing races exposed by parallel test runs
The parallel test matrix exposed three tests that raced wall-clock time. Approval-log tests slept a fixed 10 ms before reading a JSONL log that is appended fire-and-forget, so a slightly loaded event loop dropped the last record; the transcript anchor test slept a fixed 250 ms for the async tree-sitter highlighter to paint, which the parallel load exceeds; and the stall-recovery tests measured a 30 ms stall window against Date.now, so a load gap between awaited decides tripped a spurious stall nudge. Await the actual condition instead of sleeping: the approval log now exposes a flush that resolves its append tail, the transcript test polls for the newest painted row, and the stall tests inject a frozen clock, which the constructor already accepted.
1 parent 0497cda commit 51db9b6

5 files changed

Lines changed: 114 additions & 141 deletions

File tree

src/permission/approval-log.test.ts

Lines changed: 16 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,8 @@ describe("createApprovalLog", () => {
5353
now += 100; // operator decides
5454
ask.settle("allow-with-scope");
5555

56-
// Appends are fire-and-forget; give the microtask queue a turn to flush.
57-
await new Promise((r) => setTimeout(r, 10));
56+
// Appends are fire-and-forget; await the log's tail so the read sees them.
57+
await log.flush();
5858

5959
const [record] = readRecords(dir);
6060
expect(record).toBeDefined();
@@ -76,7 +76,7 @@ describe("createApprovalLog", () => {
7676
const ask = log.ask({ tool: "write_file", mode: "auto" });
7777
ask.settle("auto-allow");
7878
ask.settle("deny");
79-
await new Promise((r) => setTimeout(r, 10));
79+
await log.flush();
8080
expect(readRecords(dir)).toHaveLength(1);
8181
});
8282
});
@@ -91,21 +91,22 @@ describe("approval-log wiring through the permission gate", () => {
9191
test("logs an auto-deny for a file-mutation shell command in auto mode, with no command text", async () => {
9292
const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-"));
9393
const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-"));
94+
const log = createApprovalLog(dir);
9495
const gate = createPermissionGate({
9596
approvals: [],
9697
interactive: false,
9798
skipPermissions: false,
9899
reactorGated: false,
99100
auto: true,
100101
cwd,
101-
approvalLog: createApprovalLog(dir),
102+
approvalLog: log,
102103
});
103104
const verdict = await gate.evaluate(
104105
shellCall("echo hunter2 > /tmp/leaked-secret-file.txt"),
105106
);
106107
expect(verdict.allowed).toBe(false);
107108

108-
await new Promise((r) => setTimeout(r, 10));
109+
await log.flush();
109110
const [record] = readRecords(dir);
110111
expect(record).toBeDefined();
111112
expect(defined(record).mode).toBe("auto");
@@ -119,13 +120,14 @@ describe("approval-log wiring through the permission gate", () => {
119120
test("logs an interactive allow-once with no command text in the record", async () => {
120121
const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-"));
121122
const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-"));
123+
const log = createApprovalLog(dir);
122124
const gate = createPermissionGate({
123125
approvals: [],
124126
interactive: true,
125127
skipPermissions: false,
126128
reactorGated: false,
127129
cwd,
128-
approvalLog: createApprovalLog(dir),
130+
approvalLog: log,
129131
requestApproval: async (request) => {
130132
request.markDisplayed?.();
131133
return { allow: true };
@@ -136,7 +138,7 @@ describe("approval-log wiring through the permission gate", () => {
136138
);
137139
expect(verdict.allowed).toBe(true);
138140

139-
await new Promise((r) => setTimeout(r, 10));
141+
await log.flush();
140142
const [record] = readRecords(dir);
141143
expect(record).toBeDefined();
142144
expect(defined(record).mode).toBe("interactive");
@@ -150,18 +152,19 @@ describe("approval-log wiring through the permission gate", () => {
150152
test("logs deny with non-interactive rule when no operator is attached", async () => {
151153
const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-"));
152154
const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-"));
155+
const log = createApprovalLog(dir);
153156
const gate = createPermissionGate({
154157
approvals: [],
155158
interactive: false,
156159
skipPermissions: false,
157160
reactorGated: false,
158161
cwd,
159-
approvalLog: createApprovalLog(dir),
162+
approvalLog: log,
160163
});
161164
const verdict = await gate.evaluate(shellCall("curl https://example.com"));
162165
expect(verdict.allowed).toBe(false);
163166

164-
await new Promise((r) => setTimeout(r, 10));
167+
await log.flush();
165168
const [record] = readRecords(dir);
166169
expect(record).toBeDefined();
167170
expect(defined(record).outcome).toBe("deny");
@@ -180,13 +183,14 @@ describe("approval-log wiring through the permission gate", () => {
180183
await import("../subagent/identity-context.js");
181184
const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-"));
182185
const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-"));
186+
const log = createApprovalLog(dir);
183187
const gate = createPermissionGate({
184188
approvals: [],
185189
interactive: true,
186190
skipPermissions: false,
187191
reactorGated: false,
188192
cwd,
189-
approvalLog: createApprovalLog(dir),
193+
approvalLog: log,
190194
requestApproval: async (request) => {
191195
request.markDisplayed?.();
192196
return { allow: true };
@@ -202,7 +206,7 @@ describe("approval-log wiring through the permission gate", () => {
202206
);
203207
expect(verdict.allowed).toBe(true);
204208

205-
await new Promise((r) => setTimeout(r, 10));
209+
await log.flush();
206210
const [record] = readRecords(dir);
207211
expect(record).toBeDefined();
208212
expect(Object.keys(defined(record))).not.toContain("agentLabel");
@@ -225,7 +229,7 @@ describe("approval-log record size cap", () => {
225229
rule: "x".repeat(10_000),
226230
});
227231
ask.settle("allow-once");
228-
await new Promise((r) => setTimeout(r, 10));
232+
await log.flush();
229233
expect(readRecords(dir)).toHaveLength(0);
230234
});
231235
});

src/permission/approval-log.ts

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -133,7 +133,7 @@ export const NOOP_APPROVAL_LOG: ApprovalLog = {
133133
export function createApprovalLog(
134134
dir: string,
135135
now: () => Date = () => new Date(),
136-
): ApprovalLog {
136+
): ApprovalLog & { flush: () => Promise<void> } {
137137
const path = join(dir, APPROVAL_LOG_FILE);
138138
const log = getLogger(`${LOG_NAMESPACE_ROOT}:approval-log`);
139139
let tail: Promise<void> = Promise.resolve();
@@ -187,5 +187,9 @@ export function createApprovalLog(
187187
},
188188
};
189189
},
190+
// Resolves once every append issued so far has settled. The decision
191+
// path never awaits it; tests use it instead of a sleep to read the
192+
// log deterministically.
193+
flush: () => tail,
190194
};
191195
}

0 commit comments

Comments
 (0)