From a452c14983aa957edde155d65bd17e1990782a86 Mon Sep 17 00:00:00 2001 From: Codex Date: Wed, 27 May 2026 07:45:54 +0800 Subject: [PATCH] fix: show command execution summaries in trace --- .../code-agent-session-registry.test.mjs | 31 ++++++- internal/cloud/code-agent-trace-store.mjs | 7 ++ internal/cloud/codex-stdio-session.mjs | 90 +++++++++++++++++++ web/hwlab-cloud-web/app.mjs | 47 ++++++++++ .../scripts/trace-scroll.test.mjs | 15 ++++ 5 files changed, 188 insertions(+), 2 deletions(-) diff --git a/internal/cloud/code-agent-session-registry.test.mjs b/internal/cloud/code-agent-session-registry.test.mjs index dbeb05dd..0d4f07a9 100644 --- a/internal/cloud/code-agent-session-registry.test.mjs +++ b/internal/cloud/code-agent-session-registry.test.mjs @@ -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 { diff --git a/internal/cloud/code-agent-trace-store.mjs b/internal/cloud/code-agent-trace-store.mjs index 5cf04f1b..1819454c 100644 --- a/internal/cloud/code-agent-trace-store.mjs +++ b/internal/cloud/code-agent-trace-store.mjs @@ -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), diff --git a/internal/cloud/codex-stdio-session.mjs b/internal/cloud/codex-stdio-session.mjs index a9e89e98..36ab072e 100644 --- a/internal/cloud/codex-stdio-session.mjs +++ b/internal/cloud/codex-stdio-session.mjs @@ -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, diff --git a/web/hwlab-cloud-web/app.mjs b/web/hwlab-cloud-web/app.mjs index 0755b82a..5e1fde7e 100644 --- a/web/hwlab-cloud-web/app.mjs +++ b/web/hwlab-cloud-web/app.mjs @@ -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 ""; diff --git a/web/hwlab-cloud-web/scripts/trace-scroll.test.mjs b/web/hwlab-cloud-web/scripts/trace-scroll.test.mjs index 414d5131..385af2e2 100644 --- a/web/hwlab-cloud-web/scripts/trace-scroll.test.mjs +++ b/web/hwlab-cloud-web/scripts/trace-scroll.test.mjs @@ -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"));