fix(codex): clarify dynamic tool timeout logs

This commit is contained in:
Peter Steinberger
2026-05-01 09:10:21 +01:00
parent 7d7b610a24
commit 8a399ec5b4
2 changed files with 143 additions and 9 deletions

View File

@@ -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<never>(() => 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<unknown>)

View File

@@ -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<string, unknown>;
};
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<string, unknown> = {
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?.();
});