Skip to content

Commit 02c431c

Browse files
committed
test(runtime-node): pin FileRunLogger file output contract before async refactor
1 parent d3314c2 commit 02c431c

2 files changed

Lines changed: 458 additions & 3 deletions

File tree

Lines changed: 342 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,342 @@
1+
# Async Run Logger (Issue #276) Implementation Plan
2+
3+
> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking.
4+
5+
**Goal:** Stop `FileRunLogger` from blocking the Node event loop by replacing per-entry `appendFileSync` calls with a single append-mode `fs.createWriteStream` per run.
6+
7+
**Architecture:** `packages/runtime-node/src/run-logger.ts` keeps the exact same public `RunLogger` interface (`path`, `console`, `event`, `result`, `error`, `close` — all synchronous signatures). Internally, `FileRunLogger` opens one `WriteStream` with `flags: 'a'` in its constructor, pushes every entry through `stream.write()` (non-blocking; the stream buffers and flushes on the libuv thread pool), and `close()` ends the stream with the final `closed` marker so all buffered entries flush in order. Stream `error` events disable further logging instead of crashing the agent run. Callers (`runFrontAgentTask`, `planFrontAgentTask` in `run.ts`) are untouched.
8+
9+
**Tech Stack:** Node `fs.createWriteStream`, TypeScript, Vitest.
10+
11+
**GitNexus blast radius (recorded before editing):** `gitnexus_impact` on `FileRunLogger` and `createRunLogger` returns **HIGH** risk — direct callers `runFrontAgentTask` and `planFrontAgentTask` (`packages/runtime-node/src/run.ts`), re-export via `packages/runtime-node/src/index.ts`, indirect impact on `createFrontAgentMcpServer` / `startFrontAgentMcpServer` flows. Mitigation: the `RunLogger` interface and entry format are preserved byte-for-byte; only the write mechanism changes. Pending stream writes hold the event loop open, so the CLI's natural exit still flushes the log (no `process.exit` calls exist in `apps/cli/src`).
12+
13+
**Out of scope:** `apps/cli/src/run-logger.ts` is a legacy copy imported only by its own test file (no production import). Issue #276 targets `packages/runtime-node` only; do not touch the CLI copy.
14+
15+
---
16+
17+
### Task 1: Behavior tests for FileRunLogger file output
18+
19+
**Files:**
20+
- Modify: `packages/runtime-node/src/run-logger.test.ts`
21+
22+
- [ ] **Step 1: Write the failing tests**
23+
24+
Append to `packages/runtime-node/src/run-logger.test.ts`. Update the imports at the top of the file:
25+
26+
```ts
27+
import { mkdtempSync, readFileSync, rmSync } from 'node:fs';
28+
import { tmpdir } from 'node:os';
29+
import { join, resolve } from 'node:path';
30+
import type { AgentEvent } from '@frontagent/core';
31+
import { afterEach, describe, expect, it, vi } from 'vitest';
32+
import { createRunLogger, redactForLog, resolveRunLogPath } from './run-logger.js';
33+
```
34+
35+
Append this suite at the end of the file:
36+
37+
```ts
38+
describe('createRunLogger (file logger)', () => {
39+
const tempDirs: string[] = [];
40+
41+
function makeLogger() {
42+
const dir = mkdtempSync(join(tmpdir(), 'frontagent-runlog-'));
43+
tempDirs.push(dir);
44+
const logger = createRunLogger({
45+
projectRoot: dir,
46+
enabled: true,
47+
logFile: 'run.log',
48+
task: 'test task',
49+
provider: 'test-provider',
50+
model: 'test-model',
51+
options: {},
52+
});
53+
if (!logger) throw new Error('expected logger');
54+
return logger;
55+
}
56+
57+
async function readWhenClosed(path: string): Promise<string> {
58+
await vi.waitFor(() => {
59+
expect(readFileSync(path, 'utf8')).toContain('closed');
60+
});
61+
return readFileSync(path, 'utf8');
62+
}
63+
64+
afterEach(() => {
65+
for (const dir of tempDirs.splice(0)) {
66+
rmSync(dir, { recursive: true, force: true });
67+
}
68+
});
69+
70+
it('returns null when disabled', () => {
71+
expect(
72+
createRunLogger({
73+
projectRoot: '/tmp',
74+
enabled: false,
75+
task: 't',
76+
provider: 'p',
77+
model: 'm',
78+
options: {},
79+
}),
80+
).toBeNull();
81+
});
82+
83+
it('flushes header, entries, and close marker to the log file in order', async () => {
84+
const logger = makeLogger();
85+
logger.event({ type: 'stream_token', stepId: 's1', token: 'hello' } as AgentEvent);
86+
logger.console('warn', ['warned', { apiKey: 'sk-secret' }]);
87+
logger.result({ success: true } as never);
88+
logger.error(new Error('boom'));
89+
logger.close();
90+
91+
const content = await readWhenClosed(logger.path);
92+
expect(content).toContain('# FrontAgent Run Log');
93+
expect(content).toContain('event.stream_token');
94+
expect(content).toContain('"tokenLength": 5');
95+
expect(content).toContain('console.warn');
96+
expect(content).toContain('[REDACTED]');
97+
expect(content).not.toContain('sk-secret');
98+
expect(content).toContain('result');
99+
expect(content).toContain('boom');
100+
expect(content.indexOf('# FrontAgent Run Log')).toBeLessThan(content.indexOf('event.stream_token'));
101+
expect(content.indexOf('event.stream_token')).toBeLessThan(content.indexOf('console.warn'));
102+
expect(content.trimEnd().endsWith('closed')).toBe(true);
103+
});
104+
105+
it('ignores writes after close and is idempotent on close', async () => {
106+
const logger = makeLogger();
107+
logger.event({ type: 'status_update', label: 'before' } as AgentEvent);
108+
logger.close();
109+
logger.close();
110+
logger.event({ type: 'status_update', label: 'after-close' } as AgentEvent);
111+
logger.console('log', ['after-close-console']);
112+
113+
const content = await readWhenClosed(logger.path);
114+
expect(content).toContain('before');
115+
expect(content).not.toContain('after-close');
116+
expect(content.match(/closed/g)).toHaveLength(1);
117+
});
118+
119+
it('appends to an existing file instead of truncating', async () => {
120+
const dir = mkdtempSync(join(tmpdir(), 'frontagent-runlog-'));
121+
tempDirs.push(dir);
122+
const path = resolve(dir, 'run.log');
123+
const first = createRunLogger({
124+
projectRoot: dir,
125+
enabled: true,
126+
logFile: 'run.log',
127+
task: 'first',
128+
provider: 'p',
129+
model: 'm',
130+
options: {},
131+
});
132+
if (!first) throw new Error('expected logger');
133+
first.close();
134+
await vi.waitFor(() => {
135+
expect(readFileSync(path, 'utf8')).toContain('closed');
136+
});
137+
138+
const second = createRunLogger({
139+
projectRoot: dir,
140+
enabled: true,
141+
logFile: 'run.log',
142+
task: 'second',
143+
provider: 'p',
144+
model: 'm',
145+
options: {},
146+
});
147+
if (!second) throw new Error('expected logger');
148+
second.close();
149+
await vi.waitFor(() => {
150+
expect((readFileSync(path, 'utf8').match(/closed/g) ?? []).length).toBe(2);
151+
});
152+
153+
const content = readFileSync(path, 'utf8');
154+
expect(content).toContain('task: first');
155+
expect(content).toContain('task: second');
156+
});
157+
});
158+
```
159+
160+
Note on `task: first` / `task: second`: the header is `stringify(header)` of an object containing `task`, which JSON-stringifies as `"task": "first"`. Use these assertions instead:
161+
162+
```ts
163+
expect(content).toContain('"task": "first"');
164+
expect(content).toContain('"task": "second"');
165+
```
166+
167+
- [ ] **Step 2: Run tests — new ordering/append tests must pass against current sync implementation too (they assert behavior, not mechanism), so verify they pass, then proceed; the refactor in Task 2 must keep them green**
168+
169+
Run: `pnpm vitest run packages/runtime-node/src/run-logger.test.ts`
170+
Expected: PASS (these tests pin the existing observable contract before the internal change).
171+
172+
- [ ] **Step 3: Commit**
173+
174+
```bash
175+
git add packages/runtime-node/src/run-logger.test.ts
176+
git commit -m "test(runtime-node): pin FileRunLogger file output contract before async refactor"
177+
```
178+
179+
### Task 2: Replace appendFileSync with a single append-mode WriteStream
180+
181+
**Files:**
182+
- Modify: `packages/runtime-node/src/run-logger.ts`
183+
184+
- [ ] **Step 1: Update imports**
185+
186+
Replace line 2:
187+
188+
```ts
189+
import { appendFileSync, mkdirSync } from 'node:fs';
190+
```
191+
192+
with:
193+
194+
```ts
195+
import { createWriteStream, mkdirSync, type WriteStream } from 'node:fs';
196+
```
197+
198+
- [ ] **Step 2: Rewrite FileRunLogger to write through one stream**
199+
200+
Replace the whole `FileRunLogger` class (lines 119–162) with:
201+
202+
```ts
203+
class FileRunLogger implements RunLogger {
204+
private closed = false;
205+
private readonly stream: WriteStream;
206+
207+
constructor(
208+
readonly path: string,
209+
header: Record<string, unknown>,
210+
) {
211+
mkdirSync(dirname(path), { recursive: true });
212+
this.stream = createWriteStream(path, { flags: 'a', encoding: 'utf8' });
213+
// Disk failures (ENOSPC, EACCES, ...) must not crash the agent run; an
214+
// unhandled 'error' event on the stream would. Disable further logging instead.
215+
this.stream.on('error', () => {
216+
this.closed = true;
217+
});
218+
this.stream.write(
219+
['# FrontAgent Run Log', `startedAt: ${timestampForLine()}`, stringify(header), ''].join(
220+
'\n',
221+
),
222+
);
223+
}
224+
225+
private write(kind: string, payload: unknown): void {
226+
if (this.closed) return;
227+
this.stream.write(`[${timestampForLine()}] ${kind}\n${stringify(payload)}\n\n`);
228+
}
229+
230+
console(level: 'log' | 'warn' | 'error', args: unknown[]): void {
231+
this.write(`console.${level}`, formatConsoleArgs(args));
232+
}
233+
234+
event(event: AgentEvent): void {
235+
this.write(`event.${event.type}`, summarizeEvent(event));
236+
}
237+
238+
result(result: AgentExecutionResult): void {
239+
this.write('result', result);
240+
}
241+
242+
error(error: unknown): void {
243+
this.write('error', error);
244+
}
245+
246+
close(): void {
247+
if (this.closed) return;
248+
this.closed = true;
249+
// end() writes the final marker after all buffered entries, preserving
250+
// order, then closes the fd. Pending writes keep the event loop alive,
251+
// so a normal CLI exit still flushes the full log.
252+
this.stream.end(`[${timestampForLine()}] closed\n`);
253+
}
254+
}
255+
```
256+
257+
- [ ] **Step 3: Run the focused tests**
258+
259+
Run: `pnpm vitest run packages/runtime-node/src/run-logger.test.ts`
260+
Expected: PASS (all redaction, path, and new file-logger tests).
261+
262+
- [ ] **Step 4: Run the package tests and type check**
263+
264+
Run: `pnpm vitest run packages/runtime-node && pnpm typecheck`
265+
Expected: PASS.
266+
267+
- [ ] **Step 5: Commit**
268+
269+
```bash
270+
git add packages/runtime-node/src/run-logger.ts
271+
git commit -m "perf(runtime-node): write run log through async WriteStream instead of appendFileSync"
272+
```
273+
274+
### Task 3: Optional benchmark evidence for the PR (not committed)
275+
276+
- [ ] **Step 1: Run an ad-hoc latency comparison**
277+
278+
Write `/tmp/runlog-bench.mjs` (do NOT commit):
279+
280+
```js
281+
import { appendFileSync, createWriteStream, rmSync } from 'node:fs';
282+
import { performance } from 'node:perf_hooks';
283+
284+
const N = 5000;
285+
const entry = `[2026-06-11T00:00:00.000Z] event.stream_token\n${JSON.stringify({ type: 'stream_token', stepId: 's1', tokenLength: 4 }, null, 2)}\n\n`;
286+
287+
function pctl(samples, p) {
288+
const s = [...samples].sort((a, b) => a - b);
289+
return s[Math.min(s.length - 1, Math.floor((p / 100) * s.length))];
290+
}
291+
292+
// sync
293+
{
294+
const path = '/tmp/bench-sync.log';
295+
rmSync(path, { force: true });
296+
const samples = [];
297+
const t0 = performance.now();
298+
for (let i = 0; i < N; i++) {
299+
const a = performance.now();
300+
appendFileSync(path, entry, 'utf8');
301+
samples.push(performance.now() - a);
302+
}
303+
const total = performance.now() - t0;
304+
console.log(`appendFileSync: total=${total.toFixed(1)}ms p50=${pctl(samples, 50).toFixed(3)}ms p99=${pctl(samples, 99).toFixed(3)}ms max=${Math.max(...samples).toFixed(3)}ms (per-call event-loop block)`);
305+
}
306+
307+
// stream
308+
{
309+
const path = '/tmp/bench-stream.log';
310+
rmSync(path, { force: true });
311+
const stream = createWriteStream(path, { flags: 'a', encoding: 'utf8' });
312+
const samples = [];
313+
const t0 = performance.now();
314+
for (let i = 0; i < N; i++) {
315+
const a = performance.now();
316+
stream.write(entry);
317+
samples.push(performance.now() - a);
318+
}
319+
const submitted = performance.now() - t0;
320+
await new Promise((r) => stream.end(r));
321+
const total = performance.now() - t0;
322+
console.log(`WriteStream: submit=${submitted.toFixed(1)}ms flushTotal=${total.toFixed(1)}ms p50=${pctl(samples, 50).toFixed(3)}ms p99=${pctl(samples, 99).toFixed(3)}ms max=${Math.max(...samples).toFixed(3)}ms (per-call event-loop block)`);
323+
}
324+
```
325+
326+
Run: `node /tmp/runlog-bench.mjs`
327+
Record the output for the PR description.
328+
329+
### Task 4: Gates and PR
330+
331+
- [ ] **Step 1: Run precommit gate**
332+
333+
Run: `pnpm quality:precommit`
334+
Expected: PASS.
335+
336+
- [ ] **Step 2: GitNexus detect_changes**
337+
338+
Run `gitnexus_detect_changes()` and confirm only `run-logger.ts` symbols (`FileRunLogger`, its methods) and the test file are affected; affected flows limited to `runFrontAgentTask` / `planFrontAgentTask` logging paths.
339+
340+
- [ ] **Step 3: Open PR to develop**
341+
342+
Use the repo PR template, reference `Closes #276`, include the GitNexus impact summary (HIGH risk, interface preserved) and the benchmark numbers from Task 3.

0 commit comments

Comments
 (0)