diff --git a/extensions/codex/src/app-server/run-attempt.test.ts b/extensions/codex/src/app-server/run-attempt.test.ts index dc6ceccdf3f..fb556b34abc 100644 --- a/extensions/codex/src/app-server/run-attempt.test.ts +++ b/extensions/codex/src/app-server/run-attempt.test.ts @@ -9,6 +9,7 @@ import { } from "openclaw/plugin-sdk/agent-harness"; import { buildAgentRuntimePlan, + embeddedAgentLog, nativeHookRelayTesting, onAgentEvent, resetAgentEventsForTest, @@ -363,13 +364,61 @@ describe("runCodexAppServerAttempt", () => { await expect(response).resolves.toEqual({ success: false, contentItems: [ - { type: "inputText", text: "OpenClaw dynamic tool call timed out after 1ms." }, + { + type: "inputText", + text: "OpenClaw dynamic tool call timed out after 1ms while running tool message.", + }, ], }); expect(capturedSignal?.aborted).toBe(true); expect(onTimeout).toHaveBeenCalledTimes(1); }); + it("logs process poll timeout context separately from session idle", async () => { + vi.useFakeTimers(); + const warn = vi.spyOn(embeddedAgentLog, "warn").mockImplementation(() => undefined); + const response = __testing.handleDynamicToolCallWithTimeout({ + call: { + threadId: "thread-1", + turnId: "turn-1", + callId: "call-timeout", + namespace: null, + tool: "process", + arguments: { action: "poll", sessionId: "rapid-crustacean", timeout: 30_000 }, + }, + toolBridge: { + handleToolCall: vi.fn(() => new Promise(() => undefined)), + }, + signal: new AbortController().signal, + timeoutMs: 1, + }); + + await vi.advanceTimersByTimeAsync(1); + + await expect(response).resolves.toEqual({ + success: false, + contentItems: [ + { + type: "inputText", + text: "OpenClaw dynamic tool call timed out after 1ms while waiting for process action=poll sessionId=rapid-crustacean. This is a tool RPC timeout, not a session idle timeout.", + }, + ], + }); + expect(warn).toHaveBeenCalledWith("codex dynamic tool call timed out", { + tool: "process", + toolCallId: "call-timeout", + threadId: "thread-1", + turnId: "turn-1", + timeoutMs: 1, + timeoutKind: "codex_dynamic_tool_rpc", + processAction: "poll", + processSessionId: "rapid-crustacean", + processRequestedTimeoutMs: 30_000, + consoleMessage: + "codex process tool timeout: action=poll sessionId=rapid-crustacean toolTimeoutMs=1 requestedWaitMs=30000; per-tool-call watchdog, not session idle; repeated lines usually mean process-poll retry churn, not model progress", + }); + }); + it("releases the session when Codex never completes after a dynamic tool response", async () => { let handleRequest: | ((request: { id: string; method: string; params?: unknown }) => Promise) diff --git a/extensions/codex/src/app-server/run-attempt.ts b/extensions/codex/src/app-server/run-attempt.ts index fff8a52703b..1015b9f963c 100644 --- a/extensions/codex/src/app-server/run-attempt.ts +++ b/extensions/codex/src/app-server/run-attempt.ts @@ -89,6 +89,7 @@ const CODEX_DYNAMIC_TOOL_TIMEOUT_MS = 30_000; const CODEX_TURN_COMPLETION_IDLE_TIMEOUT_MS = 60_000; const CODEX_TURN_TERMINAL_IDLE_TIMEOUT_MS = 30 * 60_000; const CODEX_STEER_ALL_DEBOUNCE_MS = 500; +const LOG_FIELD_MAX_LENGTH = 160; type OpenClawCodingToolsOptions = NonNullable< Parameters<(typeof import("openclaw/plugin-sdk/agent-harness"))["createOpenClawCodingTools"]>[0] @@ -131,6 +132,93 @@ type CodexSteeringQueueOptions = { debounceMs?: number; }; +type DynamicToolTimeoutDetails = { + responseMessage: string; + consoleMessage: string; + meta: Record; +}; + +function normalizeLogField(value: unknown): string | undefined { + if (typeof value !== "string") { + return undefined; + } + const normalized = value + .replaceAll(String.fromCharCode(27), " ") + .replaceAll("\r", " ") + .replaceAll("\n", " ") + .replaceAll("\t", " ") + .trim(); + if (!normalized) { + return undefined; + } + return normalized.length > LOG_FIELD_MAX_LENGTH + ? `${normalized.slice(0, LOG_FIELD_MAX_LENGTH - 3)}...` + : normalized; +} + +function readNumericTimeoutMs(value: unknown): number | undefined { + if (typeof value === "number" && Number.isFinite(value)) { + return Math.max(0, Math.floor(value)); + } + if (typeof value === "string") { + const parsed = Number.parseInt(value.trim(), 10); + if (Number.isFinite(parsed)) { + return Math.max(0, Math.floor(parsed)); + } + } + return undefined; +} + +function formatDynamicToolTimeoutDetails(params: { + call: CodexDynamicToolCallParams; + timeoutMs: number; +}): DynamicToolTimeoutDetails { + const tool = normalizeLogField(params.call.tool) ?? "unknown"; + const baseMeta: Record = { + tool: params.call.tool, + toolCallId: params.call.callId, + threadId: params.call.threadId, + turnId: params.call.turnId, + timeoutMs: params.timeoutMs, + timeoutKind: "codex_dynamic_tool_rpc", + }; + + if (tool !== "process" || !isJsonObject(params.call.arguments)) { + return { + responseMessage: `OpenClaw dynamic tool call timed out after ${params.timeoutMs}ms while running tool ${tool}.`, + consoleMessage: `codex dynamic tool timeout: tool=${tool} toolTimeoutMs=${params.timeoutMs}; per-tool-call watchdog, not session idle`, + meta: baseMeta, + }; + } + + const action = normalizeLogField(params.call.arguments.action); + const sessionId = normalizeLogField(params.call.arguments.sessionId); + const requestedTimeoutMs = readNumericTimeoutMs(params.call.arguments.timeout); + const actionPart = action ? ` action=${action}` : ""; + const sessionPart = sessionId ? ` sessionId=${sessionId}` : ""; + const requestedPart = + requestedTimeoutMs === undefined ? "" : ` requestedWaitMs=${requestedTimeoutMs}`; + const retryHint = + action === "poll" + ? "; repeated lines usually mean process-poll retry churn, not model progress" + : ""; + const responseTarget = + action || sessionId + ? ` while waiting for process${actionPart}${sessionPart}` + : " while waiting for the process tool"; + + return { + responseMessage: `OpenClaw dynamic tool call timed out after ${params.timeoutMs}ms${responseTarget}. This is a tool RPC timeout, not a session idle timeout.`, + consoleMessage: `codex process tool timeout:${actionPart}${sessionPart} toolTimeoutMs=${params.timeoutMs}${requestedPart}; per-tool-call watchdog, not session idle${retryHint}`, + meta: { + ...baseMeta, + processAction: action, + processSessionId: sessionId, + processRequestedTimeoutMs: requestedTimeoutMs, + }, + }; +} + function createCodexSteeringQueue(params: { client: CodexAppServerClient; threadId: string; @@ -1112,17 +1200,14 @@ async function handleDynamicToolCallWithTimeout(params: { const timeoutMs = Math.max(1, Math.min(CODEX_DYNAMIC_TOOL_TIMEOUT_MS, params.timeoutMs)); timeout = setTimeout(() => { timedOut = true; - const message = `OpenClaw dynamic tool call timed out after ${timeoutMs}ms.`; - controller.abort(new Error(message)); + const timeoutDetails = formatDynamicToolTimeoutDetails({ call: params.call, timeoutMs }); + controller.abort(new Error(timeoutDetails.responseMessage)); params.onTimeout?.(); embeddedAgentLog.warn("codex dynamic tool call timed out", { - tool: params.call.tool, - toolCallId: params.call.callId, - threadId: params.call.threadId, - turnId: params.call.turnId, - timeoutMs, + ...timeoutDetails.meta, + consoleMessage: timeoutDetails.consoleMessage, }); - resolve(failedDynamicToolResponse(message)); + resolve(failedDynamicToolResponse(timeoutDetails.responseMessage)); }, timeoutMs); timeout.unref?.(); });