Skip to content

Commit aa93903

Browse files
ali-masterali-master
committed
feat: add detailed logger
1 parent f839a18 commit aa93903

10 files changed

Lines changed: 363 additions & 55 deletions

File tree

‎src/logger.ts‎

Lines changed: 244 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,16 @@
11
/**
2-
* Tiny leveled logger. Emits
3-
* timestamped lines on stderr, with `debug` gated behind a
4-
* verbose flag. Kept dependency-light — just chalk for colour.
2+
* Modern, streaming-friendly logger.
3+
*
4+
* Design goals:
5+
* - Informational output goes to **stdout**; only warnings/errors go to
6+
* **stderr**. (Previously everything went to stderr, which many terminals
7+
* render in red — making normal pipeline output look like failures.)
8+
* - Timestamps are 24-hour and in the device's local timezone.
9+
* - A single pinned "live" line streams what each stage is doing in real time,
10+
* keeping all of a stage's progress on one self-updating line. Permanent log
11+
* lines scroll above it; the live line stays glued to the bottom.
12+
*
13+
* Dependency-light — only `chalk` for colour, plus raw ANSI for the live line.
514
*/
615

716
import chalk from "chalk";
@@ -12,32 +21,249 @@ export function setVerbose(v: boolean): void {
1221
verbose = v;
1322
}
1423

15-
function formatMessage(...args: any[]): string {
16-
return args
17-
.map((arg) =>
18-
typeof arg === "object" ? JSON.stringify(arg, null, 2) : String(arg),
19-
)
20-
.join(" ");
21-
}
24+
// ---------------------------------------------------------------------------
25+
// Palette — a calm, modern truecolor set. Falls back gracefully when the
26+
// terminal lacks colour support (chalk handles the downgrade).
27+
// ---------------------------------------------------------------------------
28+
const c = {
29+
ts: (s: string) => chalk.hex("#6b7280")(s), // slate-500
30+
tag: (s: string) => chalk.hex("#818cf8")(s), // indigo-400
31+
stage: (s: string) => chalk.hex("#38bdf8")(s), // sky-400
32+
info: (s: string) => chalk.hex("#38bdf8")(s),
33+
success: (s: string) => chalk.hex("#34d399")(s), // emerald-400
34+
warn: (s: string) => chalk.hex("#fbbf24")(s), // amber-400
35+
error: (s: string) => chalk.hex("#f87171")(s), // red-400
36+
dim: (s: string) => chalk.dim(s),
37+
detail: (s: string) => chalk.hex("#9ca3af")(s), // gray-400
38+
};
39+
40+
const glyph = {
41+
info: "›",
42+
success: "✔",
43+
warn: "⚠",
44+
error: "✖",
45+
debug: "·",
46+
};
47+
48+
const SPINNER_FRAMES = ["⠋", "⠙", "⠹", "⠸", "⠼", "⠴", "⠦", "⠧", "⠇", "⠏"];
2249

50+
const isTTY = Boolean(process.stdout.isTTY);
51+
52+
// ---------------------------------------------------------------------------
53+
// 24-hour, local-timezone timestamp.
54+
// ---------------------------------------------------------------------------
2355
function stamp(): string {
24-
return chalk.dim(`[${new Date().toLocaleTimeString()}]`);
56+
const time = new Date().toLocaleTimeString(undefined, {
57+
hour12: false,
58+
hour: "2-digit",
59+
minute: "2-digit",
60+
second: "2-digit",
61+
});
62+
return c.ts(time);
63+
}
64+
65+
/**
66+
* Pull a leading `[tag]` (the run id) out of a message and render it as a
67+
* coloured pill, then accent the first "stage:" word. Keeps every existing
68+
* call site (`log.info("[runId] hunt: ...")`) looking modern with no churn.
69+
*/
70+
function decorate(msg: string): string {
71+
let rest = msg;
72+
let pill = "";
73+
const m = /^\[([^\]]+)\]\s*/.exec(msg);
74+
if (m) {
75+
pill = `${c.dim("[")}${c.tag(m[1])}${c.dim("]")} `;
76+
rest = msg.slice(m[0].length);
77+
}
78+
// Accent a leading "word:" or "word " stage marker.
79+
rest = rest.replace(/^([a-z][\w-]*)([: ])/i, (_, w, sep) => c.stage(w) + sep);
80+
return pill + rest;
81+
}
82+
83+
// ---------------------------------------------------------------------------
84+
// Live line (spinner) management. Only one is active at a time; stages run
85+
// sequentially at the orchestrator level, so a single pinned line is enough.
86+
// ---------------------------------------------------------------------------
87+
let active: Spinner | null = null;
88+
89+
/** Emit a permanent line, cooperating with any active live line. */
90+
function emit(stream: NodeJS.WriteStream, line: string): void {
91+
if (active && isTTY) {
92+
stream.write(`\r\x1B[2K${line}\n`);
93+
active.render();
94+
} else {
95+
stream.write(`${line}\n`);
96+
}
97+
}
98+
99+
class Spinner {
100+
private frame = 0;
101+
private detail = "";
102+
private done = 0;
103+
private readonly total: number | null;
104+
private readonly startedAt = Date.now();
105+
private timer: ReturnType<typeof setInterval> | null = null;
106+
107+
constructor(
108+
private readonly title: string,
109+
opts?: { total?: number; detail?: string },
110+
) {
111+
this.total = opts?.total ?? null;
112+
this.detail = opts?.detail ?? "";
113+
if (isTTY) {
114+
process.stdout.write("\x1B[?25l"); // hide cursor
115+
this.timer = setInterval(() => this.tick(), 80);
116+
this.timer.unref?.();
117+
this.render();
118+
} else {
119+
// Non-interactive: announce the stage start as a plain line.
120+
const head = this.total !== null ? ` (0/${this.total})` : "";
121+
process.stdout.write(`${stamp()} ${c.stage(this.title)}${head}\n`);
122+
}
123+
}
124+
125+
private tick(): void {
126+
this.frame = (this.frame + 1) % SPINNER_FRAMES.length;
127+
this.render();
128+
}
129+
130+
private elapsed(): string {
131+
const s = Math.max(0, Math.round((Date.now() - this.startedAt) / 1000));
132+
return s < 60 ? `${s}s` : `${Math.floor(s / 60)}m${s % 60}s`;
133+
}
134+
135+
/** Redraw the live line in place. */
136+
render(): void {
137+
if (!isTTY || active !== this) return;
138+
const spin = c.info(SPINNER_FRAMES[this.frame]);
139+
const counter =
140+
this.total !== null ? c.dim(` ${this.done}/${this.total}`) : "";
141+
const detail = this.detail ? ` ${c.detail(this.detail)}` : "";
142+
const elapsed = c.dim(` · ${this.elapsed()}`);
143+
process.stdout.write(
144+
`\r\x1B[2K${stamp()} ${spin} ${c.stage(this.title)}${counter}${detail}${elapsed}`,
145+
);
146+
}
147+
148+
/** Replace the streaming detail text shown on the live line. */
149+
update(detail: string): void {
150+
this.detail = detail;
151+
this.render();
152+
}
153+
154+
/** Mark one unit of work complete; optionally update the detail. */
155+
step(detail?: string): void {
156+
this.done++;
157+
if (detail !== undefined) this.detail = detail;
158+
this.render();
159+
}
160+
161+
private settle(
162+
color: (s: string) => string,
163+
mark: string,
164+
summary: string,
165+
): void {
166+
if (this.timer) {
167+
clearInterval(this.timer);
168+
this.timer = null;
169+
}
170+
if (active === this) active = null;
171+
if (isTTY) {
172+
process.stdout.write("\r\x1B[2K"); // wipe the live line
173+
process.stdout.write("\x1B[?25h"); // restore cursor
174+
}
175+
const elapsed = c.dim(`(${this.elapsed()})`);
176+
process.stdout.write(
177+
`${stamp()} ${color(mark)} ${decorate(summary)} ${elapsed}\n`,
178+
);
179+
}
180+
181+
succeed(summary: string): void {
182+
this.settle(c.success, glyph.success, summary);
183+
}
184+
185+
fail(summary: string): void {
186+
this.settle(c.error, glyph.error, summary);
187+
}
188+
189+
warn(summary: string): void {
190+
this.settle(c.warn, glyph.warn, summary);
191+
}
192+
193+
/** Stop without a final summary line. */
194+
stop(): void {
195+
if (this.timer) {
196+
clearInterval(this.timer);
197+
this.timer = null;
198+
}
199+
if (active === this) active = null;
200+
if (isTTY) process.stdout.write("\r\x1B[2K\x1B[?25h");
201+
}
202+
}
203+
204+
/** Handle returned to stages for driving their live line. */
205+
export interface StageHandle {
206+
/** Replace the streaming detail (e.g. the agent's current tool call). */
207+
readonly update: (detail: string) => void;
208+
/** Increment the progress counter; optionally set the detail. */
209+
readonly step: (detail?: string) => void;
210+
/** Finish on a green success summary. */
211+
readonly succeed: (summary: string) => void;
212+
/** Finish on a red failure summary. */
213+
readonly fail: (summary: string) => void;
214+
/** Finish on an amber warning summary. */
215+
readonly warn: (summary: string) => void;
216+
/** Stop the line without committing a summary. */
217+
readonly stop: () => void;
218+
/** Convenience sink to hand to the agent runner for live streaming. */
219+
readonly onActivity: (detail: string) => void;
25220
}
26221

27222
export const log = {
28223
info(msg: string): void {
29-
console.error(`${stamp()} ${msg}`);
224+
emit(process.stdout, `${stamp()} ${c.info(glyph.info)} ${decorate(msg)}`);
225+
},
226+
success(msg: string): void {
227+
emit(
228+
process.stdout,
229+
`${stamp()} ${c.success(glyph.success)} ${decorate(msg)}`,
230+
);
30231
},
31232
warn(msg: string): void {
32-
console.error(`${stamp()} ${chalk.yellow(msg)}`);
233+
emit(process.stderr, `${stamp()} ${c.warn(glyph.warn)} ${c.warn(msg)}`);
33234
},
34235
error(...args: any[]): void {
35-
console.error(
36-
`${stamp()} ${chalk.red(args[0])}`,
37-
chalk.red(formatMessage(...args)),
38-
);
236+
const text = args
237+
.map((a) => (typeof a === "object" ? JSON.stringify(a) : String(a)))
238+
.join(" ");
239+
emit(process.stderr, `${stamp()} ${c.error(glyph.error)} ${c.error(text)}`);
39240
},
40241
debug(msg: string): void {
41-
if (verbose) console.error(`${stamp()} ${chalk.dim(msg)}`);
242+
if (verbose)
243+
emit(process.stdout, `${stamp()} ${c.dim(glyph.debug)} ${c.dim(msg)}`);
244+
},
245+
246+
/**
247+
* Begin a live, single-line stage indicator. Subsequent `info`/`warn`/etc.
248+
* lines scroll above it; the live line stays pinned to the bottom until
249+
* `succeed`/`fail`/`warn`/`stop` is called.
250+
*/
251+
stage(
252+
title: string,
253+
opts?: { total?: number; detail?: string },
254+
): StageHandle {
255+
// Only one live line at a time — retire any previous one.
256+
active?.stop();
257+
const sp = new Spinner(title, opts);
258+
active = sp;
259+
return {
260+
update: (d) => sp.update(d),
261+
step: (d) => sp.step(d),
262+
succeed: (s) => sp.succeed(s),
263+
fail: (s) => sp.fail(s),
264+
warn: (s) => sp.warn(s),
265+
stop: () => sp.stop(),
266+
onActivity: (d) => sp.update(d),
267+
};
42268
},
43269
};

‎src/runner.ts‎

Lines changed: 55 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,12 @@ export interface RunAgentParams {
138138
repairAttempts?: number;
139139
transientRetries?: number;
140140
transientBaseDelay?: number;
141+
/**
142+
* Live-progress sink. Called with a short human description each time the
143+
* agent acts (a tool call, a thought, a chunk of reasoning) so callers can
144+
* stream what's happening on a single status line.
145+
*/
146+
onActivity?: (detail: string) => void;
141147
}
142148

143149
const sleep = (ms: number) => new Promise((r) => setTimeout(r, ms));
@@ -191,6 +197,7 @@ async function runAgentOnce(params: RunAgentParams): Promise<AgentResult> {
191197
artifactDir,
192198
artifactName,
193199
repairAttempts = 1,
200+
onActivity,
194201
} = params;
195202

196203
mkdirSync(artifactDir, { recursive: true });
@@ -245,7 +252,7 @@ async function runAgentOnce(params: RunAgentParams): Promise<AgentResult> {
245252
options,
246253
}) as AsyncGenerator<SDKMessage>;
247254

248-
const drained = await drainTurn(stream, write);
255+
const drained = await drainTurn(stream, write, onActivity);
249256
lastText = drained.text;
250257
lastResult = drained.result;
251258

@@ -273,7 +280,8 @@ async function runAgentOnce(params: RunAgentParams): Promise<AgentResult> {
273280
const repairPrompt = buildRepairPrompt(errors, schemaName);
274281
write({ kind: "repair_request", text: repairPrompt.slice(0, 50_000) });
275282
promptQueue.push(repairPrompt);
276-
const r = await drainTurn(stream, write);
283+
onActivity?.("repairing schema-invalid output");
284+
const r = await drainTurn(stream, write, onActivity);
277285
lastText = r.text;
278286
lastResult = r.result;
279287
if (lastResult.is_error) {
@@ -349,6 +357,7 @@ interface TurnResult {
349357
async function drainTurn(
350358
stream: AsyncGenerator<SDKMessage>,
351359
write: (obj: Json) => void,
360+
onActivity?: (detail: string) => void,
352361
): Promise<TurnResult> {
353362
let lastAssistantText = "";
354363
let result: Json = {};
@@ -363,6 +372,7 @@ async function drainTurn(
363372
.filter((b) => b.type === "text")
364373
.map((b) => b.text as string)
365374
.join("");
375+
if (onActivity) reportActivity(blocks, onActivity);
366376
} else if (msg.type === "result") {
367377
result = resultToDict(msg);
368378
break;
@@ -438,6 +448,49 @@ function serializeMessage(msg: Json): Json {
438448
return { kind: msg.type, ...msg };
439449
}
440450

451+
/**
452+
* Translate a turn's content blocks into a short, human-readable description
453+
* of what the agent is currently doing, for the live status line. Reports the
454+
* last meaningful block — tool calls win over prose, prose over silence.
455+
*/
456+
function reportActivity(
457+
blocks: Json[],
458+
onActivity: (detail: string) => void,
459+
): void {
460+
let latest = "";
461+
for (const b of blocks) {
462+
if (b.type === "tool_use") {
463+
latest = describeTool(b.name, b.input);
464+
} else if (b.type === "text" && typeof b.text === "string" && b.text.trim()) {
465+
latest = b.text.trim().replace(/\s+/g, " ");
466+
} else if (b.type === "thinking") {
467+
latest = "thinking…";
468+
}
469+
}
470+
if (latest) onActivity(clip(latest, 72));
471+
}
472+
473+
/** One-line summary of a tool call, e.g. `read src/app.ts` or `grep "token"`. */
474+
function describeTool(name: string, input: Json): string {
475+
const tool = String(name ?? "tool").toLowerCase();
476+
const i = input ?? {};
477+
const target =
478+
i.file_path ??
479+
i.path ??
480+
i.pattern ??
481+
i.command ??
482+
i.query ??
483+
i.url ??
484+
i.prompt ??
485+
"";
486+
const arg = target ? ` ${clip(String(target).replace(/\s+/g, " "), 48)}` : "";
487+
return `${tool}${arg}`;
488+
}
489+
490+
function clip(s: string, n: number): string {
491+
return s.length > n ? `${s.slice(0, n - 1)}…` : s;
492+
}
493+
441494
function serializeBlock(b: Json): Json {
442495
switch (b.type) {
443496
case "text":

0 commit comments

Comments
 (0)