Skip to content

Commit 0c5d31f

Browse files
MrWangJustToDoMrWangJustToDo
committed
feat(core): persist agent log to disk with rotation, log middleware hook runs
- AgentLog.attachFileSink: JSONL batch flush to .agents/logs/{sessionId}/agent.log with size-based rotation, pre-attach backfill, silent degradation without appendFile - local host mounts main-agent sink; subagents inherit session dir with own file - ensureSessionData allocates stable ses_ ids for fresh sessions - event-log-rules opens subagent:destroyed - extension logging converges into agent log (hooks category) - instrumentMiddlewareLog logs every middleware hook invocation (middleware:{name}:{hook}, phase/iteration; onChunk/sandbox skipped) - remove noisy 'After tool-compact messages' log - add validate scripts: agent-log-file-sink, agent-log-host-sink, middleware-log
1 parent 253e2b8 commit 0c5d31f

24 files changed

Lines changed: 660 additions & 19 deletions

‎packages/core/package.json‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,9 @@
2828
"validate:emit-agent-event": "pnpm run build && node scripts/validate-emit-agent-event.mjs",
2929
"validate:agent-event-envelope": "pnpm run build && node scripts/validate-agent-event-envelope.mjs",
3030
"validate:event-log-bridge": "pnpm run build && node scripts/validate-event-log-bridge.mjs",
31+
"validate:agent-log-file-sink": "pnpm run build && node scripts/validate-agent-log-file-sink.mjs",
32+
"validate:agent-log-host-sink": "pnpm run build && node scripts/validate-agent-log-host-sink.mjs",
33+
"validate:middleware-log": "pnpm run build && node scripts/validate-middleware-log.mjs",
3134
"validate:agent-status": "pnpm run build && node scripts/validate-agent-status.mjs",
3235
"validate:agent-run-finalization": "pnpm run build && node scripts/validate-agent-run-finalization.mjs",
3336
"validate:managed-agent-accessors": "pnpm run build && node scripts/validate-managed-agent-accessors.mjs",

‎packages/core/scripts/validate-agent-log-file-sink.mjs‎

Lines changed: 152 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,152 @@
1+
/**
2+
* Validates AgentLog.attachFileSink: JSONL writes, backfill of pre-attach
3+
* entries, size-based rotation, silent degradation when the env fs has no
4+
* appendFile, and detach semantics.
5+
*
6+
* Run: pnpm --filter @my-agent/core run validate:agent-log-file-sink
7+
*/
8+
9+
import assert from "node:assert/strict";
10+
import fs from "node:fs";
11+
import os from "node:os";
12+
import path from "node:path";
13+
14+
import { AgentLog, clearCoreEnv, registerCoreEnv } from "../dist/dev.mjs";
15+
16+
const sleep = (ms) => new Promise((resolve) => setTimeout(resolve, ms));
17+
18+
/** Real-fs CoreEnv (stat returns true sizes so rotation is observable). */
19+
function createEnv(rootPath, { withAppendFile }) {
20+
const fsImpl = {
21+
readFile: async (p, encoding) => fs.promises.readFile(p, encoding),
22+
writeFile: async (p, content) => fs.promises.writeFile(p, content),
23+
mkdir: async (p) => fs.promises.mkdir(p, { recursive: true }),
24+
exists: async (p) =>
25+
fs.promises.access(p).then(
26+
() => true,
27+
() => false
28+
),
29+
readdir: async (p) => {
30+
try {
31+
const entries = await fs.promises.readdir(p, { withFileTypes: true });
32+
return entries.map((e) => ({ name: e.name, type: e.isDirectory() ? "directory" : "file" }));
33+
} catch {
34+
return [];
35+
}
36+
},
37+
stat: async (p) => {
38+
const st = await fs.promises.stat(p);
39+
return { isDirectory: st.isDirectory(), isFile: st.isFile(), size: st.size, mtime: st.mtime };
40+
},
41+
remove: async (p) => fs.promises.rm(p, { recursive: true, force: true }),
42+
};
43+
if (withAppendFile) {
44+
fsImpl.appendFile = async (p, content) => fs.promises.appendFile(p, content, "utf8");
45+
}
46+
return {
47+
rootPath,
48+
getPlatform: async () => "linux",
49+
getArch: async () => "x64",
50+
getEnv: async () => ({}),
51+
homedir: async () => rootPath,
52+
fs: fsImpl,
53+
runCommand: async () => ({ stdout: "", stderr: "", code: 0 }),
54+
exec: async () => ({ stdout: "", stderr: "", code: 0 }),
55+
fetch: async () => new Response(),
56+
};
57+
}
58+
59+
const rootPath = await fs.promises.mkdtemp(path.join(os.tmpdir(), "agent-log-file-sink-"));
60+
registerCoreEnv(createEnv(rootPath, { withAppendFile: true }));
61+
62+
const logDir = path.join(rootPath, ".agents/logs/ses_test");
63+
const filePath = path.join(logDir, "agent.log");
64+
65+
// ----------------------------------------------------------------------------
66+
// 1. Backfill: entries logged before attach must be persisted first.
67+
// ----------------------------------------------------------------------------
68+
const log = new AgentLog();
69+
log.info("system", "session:start");
70+
log.error("agent", "boom-3", new Error("test error"));
71+
72+
const detach = log.attachFileSink({
73+
dir: logDir,
74+
filename: "agent.log",
75+
maxBytes: 400,
76+
maxFiles: 3,
77+
flushIntervalMs: 20,
78+
});
79+
80+
log.info("system", "hello-1");
81+
log.warn("agent", "warn-2", { n: 2 });
82+
await sleep(80);
83+
84+
const lines = (await fs.promises.readFile(filePath, "utf-8")).trim().split("\n");
85+
assert.ok(lines.length >= 4, `expected >=4 lines, got ${lines.length}`);
86+
87+
const first = JSON.parse(lines[0]);
88+
assert.equal(first.message, "session:start", "pre-attach entry backfilled first");
89+
assert.equal(first.category, "system");
90+
91+
const boom = JSON.parse(lines.find((l) => l.includes("boom-3")));
92+
assert.ok(boom.error?.message === "test error", "error field serialized as JSONL");
93+
94+
const warn = JSON.parse(lines.find((l) => l.includes("warn-2")));
95+
assert.equal(warn.data.n, 2, "data object serialized");
96+
console.log("backfill + JSONL OK:", lines.length, "lines");
97+
98+
// ----------------------------------------------------------------------------
99+
// 2. Rotation: small batches push the file past maxBytes → segment files.
100+
// ----------------------------------------------------------------------------
101+
for (let batch = 0; batch < 6; batch++) {
102+
for (let i = 0; i < 3; i++) {
103+
log.info("system", `padding-${batch}-${i}-` + "x".repeat(60));
104+
}
105+
await sleep(40);
106+
}
107+
108+
const entries = (await fs.promises.readdir(logDir)).sort();
109+
assert.ok(entries.includes("agent.log"), `active file present, got ${entries}`);
110+
const rotated = entries.filter((e) => /^agent\.log\.\d+$/.test(e));
111+
assert.ok(rotated.length >= 1, `expected >=1 rotated segment, got ${entries.join(", ")}`);
112+
console.log("rotation OK:", entries.join(", "));
113+
114+
// ----------------------------------------------------------------------------
115+
// 3. Silent degradation: fs without appendFile must not write nor throw.
116+
// ----------------------------------------------------------------------------
117+
{
118+
const noAppendRoot = await fs.promises.mkdtemp(path.join(os.tmpdir(), "agent-log-no-append-"));
119+
clearCoreEnv();
120+
registerCoreEnv(createEnv(noAppendRoot, { withAppendFile: false }));
121+
122+
const noAppendLog = new AgentLog();
123+
const noAppendDetach = noAppendLog.attachFileSink({
124+
dir: path.join(noAppendRoot, ".agents/logs/ses_quiet"),
125+
});
126+
noAppendLog.info("system", "should-not-crash");
127+
await sleep(30);
128+
noAppendDetach();
129+
130+
assert.equal(noAppendLog.getFileSinkDir(), null, "no sink dir recorded when degraded");
131+
const written = await fs.promises.readdir(noAppendRoot);
132+
assert.deepEqual(written, [], "no files written without appendFile");
133+
console.log("silent degradation OK (no appendFile → no write, no throw)");
134+
135+
// Restore the real-fs env for the detach test below.
136+
clearCoreEnv();
137+
registerCoreEnv(createEnv(rootPath, { withAppendFile: true }));
138+
}
139+
140+
// ----------------------------------------------------------------------------
141+
// 4. Detach stops writes.
142+
// ----------------------------------------------------------------------------
143+
detach();
144+
await sleep(40);
145+
const afterDetach = await fs.promises.readFile(filePath, "utf-8");
146+
log.info("system", "post-detach");
147+
await sleep(40);
148+
assert.equal(await fs.promises.readFile(filePath, "utf-8"), afterDetach, "no writes after detach");
149+
console.log("detach OK");
150+
151+
await fs.promises.rm(rootPath, { recursive: true, force: true });
152+
console.log("agent-log-file-sink validation passed");

‎packages/core/scripts/validate-agent-log-host-sink.mjs‎

Lines changed: 111 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,111 @@
1+
/**
2+
* Validates AgentLog file-sink host wiring:
3+
* 1. LocalAgentSessionHost.create() attaches the sink at
4+
* `.agents/logs/{sessionId}/agent.log` with a stable `ses_` id, backfilling
5+
* bootstrap entries (session:start) and persisting runtime entries.
6+
* 2. AgentManager.spawnSubagent inherits the parent session dir and writes an
7+
* independent `{subagentId}.log`.
8+
*
9+
* Run: pnpm --filter @my-agent/core run validate:agent-log-host-sink
10+
*/
11+
12+
import assert from "node:assert/strict";
13+
import fs from "node:fs";
14+
import os from "node:os";
15+
import path from "node:path";
16+
17+
import { AgentManager, createLocalAgentSessionHost, registerCoreEnv } from "../dist/index.mjs";
18+
19+
const sleep = (ms) => new Promise((resolve) => setTimeout(resolve, ms));
20+
21+
const rootPath = await fs.promises.mkdtemp(path.join(os.tmpdir(), "agent-log-host-sink-"));
22+
23+
/** Mirrors native-fs: relative paths resolve under rootPath, absolute pass through. */
24+
const toAbs = (p) => (path.isAbsolute(p) ? p : path.join(rootPath, p));
25+
26+
registerCoreEnv({
27+
rootPath,
28+
getPlatform: async () => "linux",
29+
getArch: async () => "x64",
30+
getEnv: async () => ({}),
31+
homedir: async () => rootPath,
32+
fs: {
33+
readFile: async (p, encoding) => fs.promises.readFile(toAbs(p), encoding),
34+
writeFile: async (p, content) => fs.promises.writeFile(toAbs(p), content),
35+
appendFile: async (p, content) => fs.promises.appendFile(toAbs(p), content, "utf8"),
36+
mkdir: async (p) => fs.promises.mkdir(toAbs(p), { recursive: true }),
37+
exists: async (p) =>
38+
fs.promises.access(toAbs(p)).then(
39+
() => true,
40+
() => false
41+
),
42+
readdir: async (p) => {
43+
try {
44+
const entries = await fs.promises.readdir(toAbs(p), { withFileTypes: true });
45+
return entries.map((e) => ({ name: e.name, type: e.isDirectory() ? "directory" : "file" }));
46+
} catch {
47+
return [];
48+
}
49+
},
50+
stat: async (p) => {
51+
const st = await fs.promises.stat(toAbs(p));
52+
return { isDirectory: st.isDirectory(), isFile: st.isFile(), size: st.size, mtime: st.mtime };
53+
},
54+
remove: async (p) => fs.promises.rm(toAbs(p), { recursive: true, force: true }),
55+
},
56+
runCommand: async () => ({ stdout: "", stderr: "", code: 0 }),
57+
exec: async () => ({ stdout: "", stderr: "", code: 0 }),
58+
fetch: async () => new Response(),
59+
});
60+
61+
const manager = new AgentManager();
62+
const host = createLocalAgentSessionHost({ manager });
63+
64+
// ----------------------------------------------------------------------------
65+
// 1. Main agent: stable ses_ id + session-scoped log dir with backfill.
66+
// ----------------------------------------------------------------------------
67+
const result = await host.create({ name: "verify", model: "test-model" });
68+
const managed = manager.getAgent(result.session.getSnapshot().agentId);
69+
assert.ok(managed, "managed agent created");
70+
71+
const sessionId = managed.ensureSessionData()?.id;
72+
assert.ok(sessionId?.startsWith("ses_"), `stable ses_ id, got ${sessionId}`);
73+
74+
managed.getLog()?.info("system", "host-level-entry");
75+
await sleep(450); // default flush interval is 250ms
76+
77+
const logDir = path.join(rootPath, ".agents/logs", sessionId);
78+
const logFile = path.join(logDir, "agent.log");
79+
assert.ok(
80+
await fs.promises.access(logFile).then(
81+
() => true,
82+
() => false
83+
),
84+
`agent.log exists`
85+
);
86+
const content = await fs.promises.readFile(logFile, "utf-8");
87+
assert.ok(content.includes("host-level-entry"), "runtime entry landed on disk");
88+
assert.ok(content.includes("session:start"), "bootstrap entry backfilled");
89+
console.log("main agent OK:", path.relative(rootPath, logDir));
90+
91+
// ----------------------------------------------------------------------------
92+
// 2. Subagent: inherits parent session dir, independent {subagentId}.log.
93+
// ----------------------------------------------------------------------------
94+
const subagent = await manager.spawnSubagent(managed.id, { name: "sub" });
95+
subagent.getLog()?.info("system", "subagent-entry");
96+
await sleep(450);
97+
98+
const subFile = path.join(logDir, `${subagent.id}.log`);
99+
assert.ok(
100+
await fs.promises.access(subFile).then(
101+
() => true,
102+
() => false
103+
),
104+
`subagent file exists`
105+
);
106+
const subContent = await fs.promises.readFile(subFile, "utf-8");
107+
assert.ok(subContent.includes("subagent-entry"), "subagent entry landed in parent session dir");
108+
console.log("subagent OK:", path.relative(rootPath, subFile));
109+
110+
await fs.promises.rm(rootPath, { recursive: true, force: true });
111+
console.log("agent-log-host-sink validation passed");

‎packages/core/scripts/validate-middleware-log.mjs‎

Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,107 @@
1+
/**
2+
* Validates instrumentMiddlewareLog: each middleware hook invocation is
3+
* recorded to the agent log (category `hooks`, debug level) with phase +
4+
* iteration, return values (sync + async/promise) pass through untouched,
5+
* high-frequency onChunk and nested sandbox hooks are skipped, and middleware
6+
* without a name fall back to "anonymous".
7+
*
8+
* Run: pnpm --filter @my-agent/core run validate:middleware-log
9+
*/
10+
11+
import assert from "node:assert/strict";
12+
13+
import { AgentLog, instrumentMiddlewareLog } from "../dist/dev.mjs";
14+
15+
// A realistic ChatMiddleware-shaped object (plain object, like the create*
16+
// factories return).
17+
const calls = [];
18+
const middleware = [
19+
{
20+
name: "test-middleware",
21+
onConfig: (ctx, config) => {
22+
calls.push({ hook: "onConfig", phase: ctx.phase, iteration: ctx.iteration });
23+
return { messages: [...config.messages, "transformed"] };
24+
},
25+
onStart: (ctx) => {
26+
calls.push({ hook: "onStart", phase: ctx.phase, iteration: ctx.iteration });
27+
},
28+
// High-frequency hooks that must NOT be logged or wrapped.
29+
onChunk: () => {
30+
calls.push({ hook: "onChunk" });
31+
return "chunk";
32+
},
33+
sandbox: {
34+
onFile: () => {},
35+
},
36+
},
37+
{
38+
// No name → anonymous fallback.
39+
onIteration: async (ctx) => {
40+
calls.push({ hook: "onIteration", phase: ctx.phase, iteration: ctx.iteration });
41+
return "iter";
42+
},
43+
},
44+
];
45+
46+
const ctx = {
47+
phase: "beforeModel",
48+
iteration: 2,
49+
};
50+
51+
const log = new AgentLog();
52+
const wrapped = instrumentMiddlewareLog(middleware, log);
53+
54+
// ----------------------------------------------------------------------------
55+
// 1. Named middleware: hooks logged + return value passed through.
56+
// ----------------------------------------------------------------------------
57+
const configOut = wrapped[0].onConfig(ctx, { messages: ["a"] });
58+
assert.deepEqual(configOut, { messages: ["a", "transformed"] }, "onConfig return passes through");
59+
assert.deepEqual(calls[0], { hook: "onConfig", phase: "beforeModel", iteration: 2 });
60+
61+
const startOut = wrapped[0].onStart(ctx);
62+
assert.equal(startOut, undefined, "onStart void return passes through");
63+
64+
// ----------------------------------------------------------------------------
65+
// 2. Anonymous middleware: async hook resolved + logged.
66+
// ----------------------------------------------------------------------------
67+
const iterOut = await wrapped[1].onIteration(ctx);
68+
assert.equal(iterOut, "iter", "async hook return passes through");
69+
assert.deepEqual(calls[2], { hook: "onIteration", phase: "beforeModel", iteration: 2 });
70+
71+
// ----------------------------------------------------------------------------
72+
// 3. onChunk / sandbox are NOT wrapped.
73+
// ----------------------------------------------------------------------------
74+
assert.equal(wrapped[0].onChunk(ctx), "chunk", "onChunk untouched");
75+
assert.equal(typeof wrapped[0].sandbox.onFile, "function", "sandbox untouched");
76+
assert.equal(wrapped[0].onChunk === middleware[0].onChunk, true, "onChunk identity preserved (not wrapped)");
77+
78+
// ----------------------------------------------------------------------------
79+
// 4. Agent log entries: category hooks, debug level, phase + iteration data.
80+
// ----------------------------------------------------------------------------
81+
const entries = log.getEntries();
82+
assert.ok(entries.length >= 2, `expected >=2 hook entries, got ${entries.length}`);
83+
for (const entry of entries) {
84+
assert.equal(entry.category, "hooks", `category hooks, got ${entry.category}`);
85+
assert.equal(entry.level, "debug", `level debug, got ${entry.level}`);
86+
}
87+
88+
assert.ok(
89+
entries.some((e) => e.message === "middleware:test-middleware:onConfig"),
90+
`has test-middleware:onConfig entry, got ${entries.map((e) => e.message).join(", ")}`
91+
);
92+
assert.ok(
93+
entries.some((e) => e.message === "middleware:anonymous:onIteration"),
94+
`has anonymous:onIteration entry, got ${entries.map((e) => e.message).join(", ")}`
95+
);
96+
assert.ok(
97+
entries.every((e) => e.message !== "middleware:test-middleware:onChunk"),
98+
"onChunk must not be logged"
99+
);
100+
101+
const onConfigEntry = entries.find((e) => e.message === "middleware:test-middleware:onConfig");
102+
assert.deepEqual(onConfigEntry.data, { phase: "beforeModel", iteration: 2 }, "phase+iteration in data");
103+
104+
console.log("named/anonymous hooks logged with phase+iteration: OK");
105+
console.log("sync + async return values passed through: OK");
106+
console.log("onChunk / sandbox skipped (identity preserved): OK");
107+
console.log("middleware-log validation passed");

0 commit comments

Comments
 (0)