fix: add headless heartbeat output

This commit is contained in:
Mikael Hugo 2026-04-29 19:29:43 +02:00
parent 93c1bbcb9a
commit 2ed1638153
3 changed files with 97 additions and 6 deletions

View file

@ -40,6 +40,16 @@ export interface ProgressContext {
isError?: boolean; // tool execution ended with an error
}
/** Context for periodic headless heartbeat lines during long quiet waits. */
export interface HeadlessHeartbeatContext {
elapsedMs: number;
quietMs: number;
totalEvents: number;
toolCallCount: number;
lastEventType?: string;
lastEventDetail?: string;
}
// ---------------------------------------------------------------------------
// ANSI Color Helpers
// ---------------------------------------------------------------------------
@ -102,7 +112,8 @@ const TUI_FOOTER_STATUS_KEYS = new Set([
function formatCategorizedNotification(message: string): string | null {
if (message.startsWith("MCP client ready")) return `[mcp] ${message}`;
if (message.startsWith("Web search:")) return `[search] ${message}`;
if (message.startsWith("Native Anthropic web search")) return `[search] ${message}`;
if (message.startsWith("Native Anthropic web search"))
return `[search] ${message}`;
if (message.includes("dispatching") && message.includes("subagents"))
return `[parallel] ${message}`;
if (message.startsWith("Slice-parallel:")) return `[parallel] ${message}`;
@ -270,6 +281,11 @@ function shortPath(p: unknown): string {
function formatDuration(ms: number): string {
if (ms < 1000) return `${ms}ms`;
if (ms >= 60_000) {
const minutes = Math.floor(ms / 60_000);
const seconds = Math.floor((ms % 60_000) / 1000);
return seconds > 0 ? `${minutes}m${seconds}s` : `${minutes}m`;
}
const s = (ms / 1000).toFixed(1);
return `${s}s`;
}
@ -403,7 +419,9 @@ export function formatProgress(
if (statusKey) {
const label = parsePhaseLabel(statusKey, msg);
if (label) {
const labelTag = isPhaseStatusKey(statusKey) ? tag("phase") : tag("status");
const labelTag = isPhaseStatusKey(statusKey)
? tag("phase")
: tag("status");
return `${c.cyan}${labelTag}${label}${c.reset}`;
}
}
@ -474,6 +492,21 @@ export function formatCostLine(
return `${c.dim}${tag("cost")}$${costUsd.toFixed(4)} (${inputTokens + outputTokens} tokens)${c.reset}`;
}
/**
* Format a periodic liveness line for headless runs.
*
* Purpose: make long model calls and quiet auto-mode phases observable without
* changing machine-readable JSON output.
*/
export function formatHeadlessHeartbeat(ctx: HeadlessHeartbeatContext): string {
const lastEvent = ctx.lastEventType
? ctx.lastEventDetail
? `${ctx.lastEventType}:${ctx.lastEventDetail}`
: ctx.lastEventType
: "none";
return `${c.dim}${tag("headless")}still running ${formatDuration(ctx.elapsedMs)}; quiet ${formatDuration(ctx.quietMs)}; last=${lastEvent}; events=${ctx.totalEvents}; tools=${ctx.toolCallCount}${c.reset}`;
}
// ---------------------------------------------------------------------------
// Phase Label Parser
// ---------------------------------------------------------------------------

View file

@ -45,6 +45,7 @@ import type { HeadlessJsonResult, OutputFormat } from "./headless-types.js";
import { VALID_OUTPUT_FORMATS } from "./headless-types.js";
import type { ExtensionUIRequest, ProgressContext } from "./headless-ui.js";
import {
formatHeadlessHeartbeat,
formatProgress,
formatTextEnd,
formatTextStart,
@ -74,6 +75,8 @@ import {
traceEvent,
} from "./resources/extensions/sf/trace-collector.js";
const HEADLESS_HEARTBEAT_INTERVAL_MS = 60_000;
// ---------------------------------------------------------------------------
// Types
// ---------------------------------------------------------------------------
@ -552,6 +555,7 @@ async function runHeadlessOnce(
let exitCode = 0;
let milestoneReady = false; // tracks "Milestone X ready." for auto-chaining
const recentEvents: TrackedEvent[] = [];
let lastVisibleProgressAt = Date.now();
const interactiveToolCallIds = new Set<string>();
// JSON batch mode: cost aggregation (cumulative-max pattern per K004)
@ -756,6 +760,11 @@ async function runHeadlessOnce(
recentEvents.push({ type, timestamp: Date.now(), detail });
if (recentEvents.length > 20) recentEvents.shift();
}
function writeHeadlessLine(line: string): void {
process.stderr.write(line + "\n");
lastVisibleProgressAt = Date.now();
}
// Client started flag — replaces old stdinWriter null-check
let clientStarted = false;
@ -830,6 +839,27 @@ async function runHeadlessOnce(
resolveCompletion();
}, options.timeout)
: null;
const heartbeatTimer =
!options.json && options.outputFormat === "text"
? setInterval(() => {
if (completed) return;
const now = Date.now();
const quietMs = now - lastVisibleProgressAt;
if (quietMs < HEADLESS_HEARTBEAT_INTERVAL_MS) return;
const lastEvent = recentEvents[recentEvents.length - 1];
writeHeadlessLine(
formatHeadlessHeartbeat({
elapsedMs: now - startTime,
quietMs,
totalEvents,
toolCallCount,
lastEventType: lastEvent?.type,
lastEventDetail: lastEvent?.detail,
}),
);
}, HEADLESS_HEARTBEAT_INTERVAL_MS)
: null;
// Event handler
client.onEvent((event) => {
@ -945,6 +975,7 @@ async function runHeadlessOnce(
// --- Text streaming ---
if (ameType === "text_start") {
inTextBlock = true;
lastVisibleProgressAt = Date.now();
process.stderr.write(formatTextStart());
} else if (ameType === "text_delta") {
const delta = String(ame.delta ?? ame.text ?? "");
@ -954,10 +985,12 @@ async function runHeadlessOnce(
inTextBlock = true;
process.stderr.write(formatTextStart());
}
lastVisibleProgressAt = Date.now();
process.stderr.write(delta);
}
} else if (ameType === "text_end") {
if (inTextBlock) {
lastVisibleProgressAt = Date.now();
process.stderr.write(formatTextEnd() + "\n");
inTextBlock = false;
}
@ -966,6 +999,7 @@ async function runHeadlessOnce(
// --- Thinking streaming ---
else if (ameType === "thinking_start") {
inThinkingBlock = true;
lastVisibleProgressAt = Date.now();
process.stderr.write(formatThinkingStart());
} else if (ameType === "thinking_delta") {
const delta = String(ame.delta ?? ame.text ?? "");
@ -974,10 +1008,12 @@ async function runHeadlessOnce(
inThinkingBlock = true;
process.stderr.write(formatThinkingStart());
}
lastVisibleProgressAt = Date.now();
process.stderr.write(delta);
}
} else if (ameType === "thinking_end") {
if (inThinkingBlock) {
lastVisibleProgressAt = Date.now();
process.stderr.write(formatThinkingEnd() + "\n");
inThinkingBlock = false;
}
@ -1015,7 +1051,7 @@ async function runHeadlessOnce(
thinkingBuffer.trim() &&
(eventType === "tool_execution_start" || eventType === "message_end")
) {
process.stderr.write(formatThinkingLine(thinkingBuffer) + "\n");
writeHeadlessLine(formatThinkingLine(thinkingBuffer));
thinkingBuffer = "";
}
@ -1041,7 +1077,7 @@ async function runHeadlessOnce(
const line = formatProgress(eventObj, ctx);
if (line && line !== lastProgressLine) {
process.stderr.write(line + "\n");
writeHeadlessLine(line);
lastProgressLine = line;
}
}
@ -1183,6 +1219,7 @@ async function runHeadlessOnce(
);
}
if (timeoutTimer) clearTimeout(timeoutTimer);
if (heartbeatTimer) clearInterval(heartbeatTimer);
if (idleTimer) clearTimeout(idleTimer);
// Emit batch JSON result if in json mode before exiting
if (options.outputFormat === "json") {
@ -1201,6 +1238,7 @@ async function runHeadlessOnce(
process.stderr.write(
`[headless] Error: Failed to start RPC session: ${err instanceof Error ? err.message : String(err)}\n`,
);
if (heartbeatTimer) clearInterval(heartbeatTimer);
if (timeoutTimer) clearTimeout(timeoutTimer);
process.exit(1);
}
@ -1287,8 +1325,8 @@ async function runHeadlessOnce(
}
if (!options.json) {
process.stderr.write(
`[headless] Running /sf ${options.command}${options.commandArgs.length > 0 ? " " + options.commandArgs.join(" ") : ""}...\n`,
writeHeadlessLine(
`[headless] Running /sf ${options.command}${options.commandArgs.length > 0 ? " " + options.commandArgs.join(" ") : ""}...`,
);
}
@ -1348,6 +1386,7 @@ async function runHeadlessOnce(
// Cleanup
if (timeoutTimer) clearTimeout(timeoutTimer);
if (heartbeatTimer) clearInterval(heartbeatTimer);
if (idleTimer) clearTimeout(idleTimer);
for (const timer of pendingResponseTimers.values()) clearTimeout(timer);
pendingResponseTimers.clear();

View file

@ -3,6 +3,7 @@ import { describe, it } from "node:test";
import type { ProgressContext } from "../headless-ui.js";
import {
formatCostLine,
formatHeadlessHeartbeat,
formatProgress,
formatThinkingLine,
summarizeToolArgs,
@ -16,6 +17,24 @@ function ctx(overrides: Partial<ProgressContext> = {}): ProgressContext {
}
describe("formatProgress", () => {
describe("formatHeadlessHeartbeat", () => {
it("shows liveness details during quiet headless waits", () => {
const result = formatHeadlessHeartbeat({
elapsedMs: 125_000,
quietMs: 61_000,
totalEvents: 12,
toolCallCount: 3,
lastEventType: "agent_start",
});
assert.ok(result.includes("still running 2m5s"));
assert.ok(result.includes("quiet 1m1s"));
assert.ok(result.includes("last=agent_start"));
assert.ok(result.includes("events=12"));
assert.ok(result.includes("tools=3"));
});
});
describe("tool_execution_start", () => {
it("shows tool name and summarized args in verbose mode", () => {
const result = formatProgress(