fix: show command execution summaries in trace
This commit is contained in:
@@ -1057,7 +1057,7 @@ function codeAgentBlockedPayloadFromAcquire(acquireResult, { conversationId, tra
|
||||
};
|
||||
}
|
||||
|
||||
function createTimedFakeAppServerClient({ calls, text = "timed stdio reply", eventEveryMs = 20, eventCount = 0, completeAfterMs = null } = {}) {
|
||||
function createTimedFakeAppServerClient({ calls, text = "timed stdio reply", eventEveryMs = 20, eventCount = 0, completeAfterMs = null, commandExecution = null } = {}) {
|
||||
let notificationHandler = null;
|
||||
let turn = 0;
|
||||
const timers = new Set();
|
||||
@@ -1099,6 +1099,19 @@ function createTimedFakeAppServerClient({ calls, text = "timed stdio reply", eve
|
||||
});
|
||||
});
|
||||
}
|
||||
if (commandExecution) {
|
||||
const commandItem = {
|
||||
id: commandExecution.id ?? "cmd_stdio_timed_1",
|
||||
type: "commandExecution",
|
||||
...commandExecution
|
||||
};
|
||||
later(Math.max(1, Math.floor(eventEveryMs / 2)), () => {
|
||||
notificationHandler?.({ method: "item/started", params: { item: { ...commandItem, status: "running" } } });
|
||||
});
|
||||
later(eventEveryMs, () => {
|
||||
notificationHandler?.({ method: "item/completed", params: { item: { ...commandItem, status: commandExecution.status ?? "completed" } } });
|
||||
});
|
||||
}
|
||||
if (Number.isInteger(completeAfterMs)) {
|
||||
later(completeAfterMs, () => {
|
||||
notificationHandler?.({ method: "item/agentMessage/delta", params: { itemId: `item_${turn}`, delta: text } });
|
||||
@@ -1552,7 +1565,14 @@ test("Codex app-server activity timeout does not fail an active turn", async ()
|
||||
text: "active turn completed",
|
||||
eventEveryMs: 20,
|
||||
eventCount: 5,
|
||||
completeAfterMs: 130
|
||||
completeAfterMs: 130,
|
||||
commandExecution: {
|
||||
id: "cmd_stdio_trace_summary",
|
||||
command: ["tran_cmd", "gws_DESKTOP:/f/work/constart", "dir"],
|
||||
exitCode: 0,
|
||||
durationMs: 456,
|
||||
aggregatedOutput: "FREQ_Controller_FW.uvprojx\nkeil\n"
|
||||
}
|
||||
})
|
||||
});
|
||||
const env = {
|
||||
@@ -1590,6 +1610,13 @@ test("Codex app-server activity timeout does not fail an active turn", async ()
|
||||
assert.equal(payload.reply.content, "active turn completed");
|
||||
assert.ok(Date.now() - started >= 100);
|
||||
assert.ok(payload.runnerTrace.events.some((event) => event.label === "item/commandExecution/outputDelta"));
|
||||
const commandEvent = payload.runnerTrace.events.find((event) => event.label === "item/commandExecution:completed");
|
||||
assert.ok(commandEvent, JSON.stringify(payload.runnerTrace.events));
|
||||
assert.equal(commandEvent.toolName, "commandExecution");
|
||||
assert.equal(commandEvent.command, "tran_cmd gws_DESKTOP:/f/work/constart dir");
|
||||
assert.equal(commandEvent.exitCode, 0);
|
||||
assert.equal(commandEvent.durationMs, 456);
|
||||
assert.match(commandEvent.stdoutSummary, /FREQ_Controller_FW\.uvprojx/);
|
||||
assert.equal(payload.runnerTrace.events.some((event) => event.label === "timeout:no_activity"), false);
|
||||
assert.equal(payload.error, undefined);
|
||||
} finally {
|
||||
|
||||
@@ -322,8 +322,15 @@ function normalizeTraceEvent(event, { traceId, seq, now, fallbackRunnerKind } =
|
||||
sessionReused: typeof event.sessionReused === "boolean" ? event.sessionReused : undefined,
|
||||
turn: typeof event.turn === "number" ? event.turn : undefined,
|
||||
toolName,
|
||||
itemId: safeText(event.itemId, 180),
|
||||
command: safeText(event.command, 900),
|
||||
exitCode: Number.isInteger(event.exitCode) ? event.exitCode : undefined,
|
||||
durationMs: typeof event.durationMs === "number" ? Math.max(0, Math.trunc(event.durationMs)) : undefined,
|
||||
outputBytes: typeof event.outputBytes === "number" ? Math.max(0, Math.trunc(event.outputBytes)) : undefined,
|
||||
promptSummary: safeText(event.promptSummary, 240),
|
||||
outputSummary: safeText(event.outputSummary, 400),
|
||||
stdoutSummary: safeText(event.stdoutSummary, 600),
|
||||
stderrSummary: safeText(event.stderrSummary, 600),
|
||||
chunk: safeText(event.chunk, 400),
|
||||
message: safeText(event.message, 500),
|
||||
errorCode: safeText(event.errorCode, 120),
|
||||
|
||||
@@ -1731,6 +1731,20 @@ function createAppServerTurnState({ traceRecorder, session } = {}) {
|
||||
});
|
||||
return;
|
||||
}
|
||||
if (method === "item/started" && item?.type === "commandExecution") {
|
||||
appendCommandExecutionTrace(item, {
|
||||
status: "started",
|
||||
label: "item/commandExecution:started"
|
||||
});
|
||||
return;
|
||||
}
|
||||
if (method === "item/completed" && item?.type === "commandExecution") {
|
||||
appendCommandExecutionTrace(item, {
|
||||
status: appServerCommandStatus(item),
|
||||
label: "item/commandExecution:completed"
|
||||
});
|
||||
return;
|
||||
}
|
||||
if (method === "item/commandExecution/outputDelta" || method === "item/reasoning/summaryTextDelta" || method === "item/reasoning/textDelta") {
|
||||
appendTrace({
|
||||
type: method.startsWith("item/reasoning/") ? "reasoning" : "tool_call",
|
||||
@@ -1790,6 +1804,30 @@ function createAppServerTurnState({ traceRecorder, session } = {}) {
|
||||
}
|
||||
}
|
||||
|
||||
function appendCommandExecutionTrace(item, { status, label }) {
|
||||
const output = commandExecutionOutputText(item);
|
||||
appendTrace({
|
||||
type: "tool_call",
|
||||
stage: "tool_call",
|
||||
status,
|
||||
label,
|
||||
itemId: optionalId(item.id),
|
||||
toolName: "commandExecution",
|
||||
command: redactText(commandExecutionCommandText(item)),
|
||||
exitCode: Number.isInteger(item.exitCode) ? item.exitCode : undefined,
|
||||
durationMs: typeof item.durationMs === "number" ? item.durationMs : undefined,
|
||||
outputBytes: output.length,
|
||||
stdoutSummary: output ? tailText(redactText(output), 600) : undefined,
|
||||
stderrSummary: commandExecutionErrorText(item),
|
||||
sessionId: session?.sessionId,
|
||||
sessionStatus: session?.status,
|
||||
turn: session?.turn,
|
||||
threadId,
|
||||
turnId,
|
||||
waitingFor: status === "completed" ? "turn/completed" : "commandExecution/completed"
|
||||
});
|
||||
}
|
||||
|
||||
async function wait(timeoutMs, closedPromise, { hardTimeoutMs = null } = {}) {
|
||||
let activityTimer;
|
||||
let hardTimer;
|
||||
@@ -2017,6 +2055,58 @@ function appServerTerminalStatus(value) {
|
||||
return raw ? "failed" : null;
|
||||
}
|
||||
|
||||
function appServerCommandStatus(item) {
|
||||
const raw = String(item?.status ?? "").trim().toLowerCase();
|
||||
if (raw === "completed" || raw === "complete" || raw === "success" || raw === "succeeded") return "completed";
|
||||
if (raw === "failed" || raw === "error") return "failed";
|
||||
if (Number.isInteger(item?.exitCode)) return item.exitCode === 0 ? "completed" : "failed";
|
||||
return raw || "completed";
|
||||
}
|
||||
|
||||
function commandExecutionCommandText(item) {
|
||||
return firstCommandExecutionText(
|
||||
item?.command,
|
||||
item?.cmd,
|
||||
item?.argv,
|
||||
item?.input,
|
||||
item?.metadata?.command
|
||||
);
|
||||
}
|
||||
|
||||
function commandExecutionOutputText(item) {
|
||||
return firstCommandExecutionText(
|
||||
item?.aggregatedOutput,
|
||||
item?.output,
|
||||
item?.stdout,
|
||||
item?.result,
|
||||
item?.metadata?.output
|
||||
);
|
||||
}
|
||||
|
||||
function commandExecutionErrorText(item) {
|
||||
const error = item?.error;
|
||||
const message = typeof error === "string" ? error : typeof error?.message === "string" ? error.message : "";
|
||||
const text = firstCommandExecutionText(item?.stderr, message, item?.metadata?.stderr);
|
||||
return text ? tailText(redactText(text), 600) : undefined;
|
||||
}
|
||||
|
||||
function firstCommandExecutionText(...values) {
|
||||
for (const value of values) {
|
||||
const text = commandExecutionTextValue(value);
|
||||
if (text) return text;
|
||||
}
|
||||
return "";
|
||||
}
|
||||
|
||||
function commandExecutionTextValue(value) {
|
||||
if (typeof value === "string") return value.trim();
|
||||
if (Array.isArray(value)) return value.map((item) => commandExecutionTextValue(item)).filter(Boolean).join(" ").trim();
|
||||
if (value && typeof value === "object") {
|
||||
return firstCommandExecutionText(value.text, value.content, value.message, value.stdout, value.stderr, value.command, value.cmd);
|
||||
}
|
||||
return "";
|
||||
}
|
||||
|
||||
export function longLivedSessionGate({
|
||||
provider,
|
||||
runnerKind,
|
||||
|
||||
@@ -5034,6 +5034,7 @@ function compactTraceTextTail(text, maxLength) {
|
||||
|
||||
function traceDisplayRow(trace, event, options = {}) {
|
||||
if (!options.includeNoise && isNoisyTraceEvent(event)) return null;
|
||||
if (isCommandExecutionTraceEvent(event)) return traceCommandExecutionRow(trace, event);
|
||||
const clock = traceClock(event.createdAt);
|
||||
const total = formatTraceDuration(traceRelativeMs(trace, event));
|
||||
const status = traceStatusToken(event);
|
||||
@@ -5054,6 +5055,43 @@ function traceDisplayRow(trace, event, options = {}) {
|
||||
};
|
||||
}
|
||||
|
||||
function traceCommandExecutionRow(trace, event) {
|
||||
const clock = traceClock(event.createdAt);
|
||||
const total = formatTraceDuration(traceRelativeMs(trace, event));
|
||||
const status = traceStatusToken(event);
|
||||
const command = cleanTraceOutputText(event.command ?? "");
|
||||
const meta = [
|
||||
status,
|
||||
"tool cmd",
|
||||
command ? `:: ${compactTraceTextTail(command, 220)}` : null,
|
||||
Number.isInteger(event.exitCode) ? `exit=${event.exitCode}` : null,
|
||||
typeof event.durationMs === "number" ? `s=${(event.durationMs / 1000).toFixed(1)}` : null,
|
||||
typeof event.outputBytes === "number" ? `out=${formatTraceBytes(event.outputBytes)}` : null,
|
||||
event.itemId ? `item=${event.itemId}` : null
|
||||
].filter(Boolean).join(" ");
|
||||
return {
|
||||
seq: event.seq ?? null,
|
||||
tone: traceEventTone(event),
|
||||
header: `${clock} total=${total} ${meta}`,
|
||||
body: traceCommandExecutionBody(event)
|
||||
};
|
||||
}
|
||||
|
||||
function traceCommandExecutionBody(event) {
|
||||
const lines = [
|
||||
event.command ? `command=${compactTraceTextTail(cleanTraceOutputText(event.command), 900)}` : null,
|
||||
event.stdoutSummary ? `stdout:\n${compactTraceTextTail(cleanTraceOutputText(event.stdoutSummary), 1200)}` : null,
|
||||
event.stderrSummary ? `stderr:\n${compactTraceTextTail(cleanTraceOutputText(event.stderrSummary), 800)}` : null,
|
||||
event.waitingFor && event.status !== "completed" ? `waiting=${event.waitingFor}` : null
|
||||
].filter(Boolean);
|
||||
return lines.join("\n");
|
||||
}
|
||||
|
||||
function isCommandExecutionTraceEvent(event) {
|
||||
return event?.type === "tool_call" && event?.toolName === "commandExecution" &&
|
||||
(event?.label === "item/commandExecution:started" || event?.label === "item/commandExecution:completed");
|
||||
}
|
||||
|
||||
function isNoisyTraceEvent(event) {
|
||||
const label = String(event?.label ?? "");
|
||||
if (isToolOutputChunkTraceEvent(event)) return false;
|
||||
@@ -5082,6 +5120,8 @@ function readableTraceLabel(event) {
|
||||
if (label === "request:accepted") return "request accepted";
|
||||
if (label.startsWith("tool:codex-app-server.thread/start+turn/start")) return "codex turn start";
|
||||
if (label.startsWith("tool:codex-app-server.thread/resume+turn/start")) return "codex turn resume";
|
||||
if (label === "item/commandExecution:started") return "cmd started";
|
||||
if (label === "item/commandExecution:completed") return "cmd completed";
|
||||
if (label.startsWith("item/commandExecution/outputDelta")) return "cmd output";
|
||||
if (label === "turn:waiting:first_assistant_token") return "waiting first assistant token";
|
||||
if (label.startsWith("turn:completed")) return "turn completed";
|
||||
@@ -5252,6 +5292,13 @@ function compactTraceSize(value) {
|
||||
return String(length);
|
||||
}
|
||||
|
||||
function formatTraceBytes(value) {
|
||||
const bytes = Math.max(0, Number(value) || 0);
|
||||
if (bytes >= 1024 * 1024) return `${(bytes / 1024 / 1024).toFixed(1)}MiB`;
|
||||
if (bytes >= 1024) return `${(bytes / 1024).toFixed(1)}KiB`;
|
||||
return `${bytes}B`;
|
||||
}
|
||||
|
||||
function cleanTraceText(value) {
|
||||
const text = String(value ?? "").trim();
|
||||
if (!text) return "";
|
||||
|
||||
@@ -160,6 +160,18 @@ test("trace display full means complete readable timeline, not compacted result
|
||||
status: "started",
|
||||
message: "accepted"
|
||||
},
|
||||
{
|
||||
label: "item/commandExecution:completed",
|
||||
type: "tool_call",
|
||||
status: "completed",
|
||||
toolName: "commandExecution",
|
||||
command: "node /app/tools/hwlab-gateway-shell.mjs --json --timeout-ms 120000",
|
||||
exitCode: 0,
|
||||
durationMs: 1234,
|
||||
outputBytes: 42,
|
||||
stdoutSummary: "gateway stdout ok",
|
||||
stderrSummary: ""
|
||||
},
|
||||
{
|
||||
label: "item/commandExecution/outputDelta",
|
||||
type: "tool_call",
|
||||
@@ -183,6 +195,9 @@ test("trace display full means complete readable timeline, not compacted result
|
||||
const replaying = await tracePanelText(page);
|
||||
assert.match(replaying.count, /完整 trace 回放中/);
|
||||
assert.doesNotMatch(replaying.count, /压缩窗口|显示全部/);
|
||||
assert.ok(replaying.rows.some((row) => row.includes("tool cmd :: node /app/tools/hwlab-gateway-shell.mjs --json") && row.includes("exit=0") && row.includes("s=1.2") && row.includes("out=42B")), replaying.rows.join("\n"));
|
||||
assert.doesNotMatch(replaying.rows.join("\n"), /node \/ app \/ tools/);
|
||||
assert.match(replaying.bodies.join("\n"), /stdout:\s*gateway stdout ok/);
|
||||
assert.equal(replaying.rows.filter((row) => row.includes("tool gateway.shell")).length, 2, replaying.rows.join("\n---\n"));
|
||||
assert.ok(replaying.rows.some((row) => row.includes("op=op_one")), replaying.rows.join("\n"));
|
||||
assert.ok(replaying.rows.some((row) => row.includes("op=op_two")), replaying.rows.join("\n"));
|
||||
|
||||
Reference in New Issue
Block a user