Skip to content

Commit 72140c0

Browse files
author
ai-hpc
committed
fix(codex): trace app-server thread lifecycle timing
1 parent f499841 commit 72140c0

2 files changed

Lines changed: 391 additions & 56 deletions

File tree

‎extensions/codex/src/app-server/thread-lifecycle.test.ts‎

Lines changed: 276 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,8 @@
1+
import fs from "node:fs/promises";
2+
import os from "node:os";
3+
import path from "node:path";
14
import type { EmbeddedRunAttemptParams } from "openclaw/plugin-sdk/agent-harness-runtime";
2-
import { describe, expect, it } from "vitest";
5+
import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
36
import { CODEX_GPT5_BEHAVIOR_CONTRACT } from "../../prompt-overlay.js";
47
import {
58
buildDeveloperInstructions,
@@ -8,8 +11,15 @@ import {
811
buildThreadResumeParams,
912
buildThreadStartParams,
1013
codexDynamicToolsFingerprint,
14+
formatCodexThreadLifecycleTimingSummary,
1115
resolveReasoningEffort,
16+
shouldWarnCodexThreadLifecycleTimingSummary,
17+
startOrResumeThread,
18+
type CodexThreadLifecycleTimingLogger,
1219
} from "./thread-lifecycle.js";
20+
import { createCodexTestModel } from "./test-support.js";
21+
22+
let tempDir: string;
1323

1424
function createAttemptParams(params: {
1525
provider: string;
@@ -61,6 +71,101 @@ function createAppServerOptions() {
6171
} as const;
6272
}
6373

74+
function createThreadLifecycleParams(
75+
sessionFile: string,
76+
workspaceDir: string,
77+
): EmbeddedRunAttemptParams {
78+
return {
79+
prompt: "hello",
80+
sessionId: "session-1",
81+
sessionKey: "agent:main:session-1",
82+
sessionFile,
83+
workspaceDir,
84+
runId: "run-1",
85+
provider: "codex",
86+
modelId: "gpt-5.4-codex",
87+
model: createCodexTestModel("codex"),
88+
thinkLevel: "medium",
89+
disableTools: true,
90+
timeoutMs: 5_000,
91+
authStorage: {} as never,
92+
authProfileStore: { version: 1, profiles: {} },
93+
modelRegistry: {} as never,
94+
} as EmbeddedRunAttemptParams;
95+
}
96+
97+
function createThreadLifecycleAppServerOptions(): Parameters<
98+
typeof startOrResumeThread
99+
>[0]["appServer"] {
100+
return {
101+
start: {
102+
transport: "stdio",
103+
command: "codex",
104+
args: ["app-server"],
105+
headers: {},
106+
},
107+
requestTimeoutMs: 60_000,
108+
turnCompletionIdleTimeoutMs: 60_000,
109+
approvalPolicy: "never",
110+
approvalsReviewer: "user",
111+
sandbox: "workspace-write",
112+
};
113+
}
114+
115+
function threadStartResult(threadId = "thread-1") {
116+
return {
117+
thread: {
118+
id: threadId,
119+
sessionId: "session-1",
120+
forkedFromId: null,
121+
preview: "",
122+
ephemeral: false,
123+
modelProvider: "openai",
124+
createdAt: 1,
125+
updatedAt: 1,
126+
status: { type: "idle" },
127+
path: null,
128+
cwd: tempDir,
129+
cliVersion: "0.125.0",
130+
source: "unknown",
131+
agentNickname: null,
132+
agentRole: null,
133+
gitInfo: null,
134+
name: null,
135+
turns: [],
136+
},
137+
model: "gpt-5.4-codex",
138+
modelProvider: "openai",
139+
serviceTier: null,
140+
cwd: tempDir,
141+
instructionSources: [],
142+
approvalPolicy: "never",
143+
approvalsReviewer: "user",
144+
sandbox: { type: "dangerFullAccess" },
145+
permissionProfile: null,
146+
reasoningEffort: null,
147+
};
148+
}
149+
150+
function createTimingLogger(traceEnabled: boolean): CodexThreadLifecycleTimingLogger {
151+
return {
152+
isEnabled: vi.fn((level: "trace") => level === "trace" && traceEnabled),
153+
trace: vi.fn(),
154+
warn: vi.fn(),
155+
};
156+
}
157+
158+
function expectSingleLogMessage(
159+
log: CodexThreadLifecycleTimingLogger,
160+
level: "trace" | "warn",
161+
): string {
162+
const mock = log[level] as ReturnType<typeof vi.fn>;
163+
expect(mock).toHaveBeenCalledTimes(1);
164+
const message = mock.mock.calls[0]?.[0];
165+
expect(typeof message).toBe("string");
166+
return message as string;
167+
}
168+
64169
describe("Codex app-server native code mode config", () => {
65170
it("keeps Codex-native subagents primary while limiting OpenClaw spawn to OpenClaw delegation", () => {
66171
const instructions = buildDeveloperInstructions(createAttemptParams({ provider: "openai" }));
@@ -586,6 +691,176 @@ describe("Codex app-server model provider selection", () => {
586691
});
587692
});
588693

694+
describe("Codex app-server thread lifecycle timing", () => {
695+
beforeEach(async () => {
696+
tempDir = await fs.mkdtemp(path.join(os.tmpdir(), "openclaw-codex-thread-lifecycle-"));
697+
});
698+
699+
afterEach(async () => {
700+
await fs.rm(tempDir, { recursive: true, force: true });
701+
vi.restoreAllMocks();
702+
});
703+
704+
it("formats stage summaries with run, session, action, and elapsed timing", () => {
705+
const message = formatCodexThreadLifecycleTimingSummary({
706+
runId: "run-a",
707+
sessionId: "session-a",
708+
sessionKey: "agent:main:session-a",
709+
action: "started",
710+
summary: {
711+
totalMs: 12,
712+
spans: [
713+
{ name: "read-binding", durationMs: 4, elapsedMs: 4 },
714+
{ name: "thread-start-request", durationMs: 8, elapsedMs: 12 },
715+
],
716+
},
717+
});
718+
719+
expect(message).toBe(
720+
"[trace:codex-app-server] thread lifecycle: runId=run-a sessionId=session-a " +
721+
"sessionKey=agent:main:session-a action=started totalMs=12 " +
722+
"stages=read-binding:4ms@4ms,thread-start-request:8ms@12ms",
723+
);
724+
});
725+
726+
it("warns when the total or a single stage crosses the lifecycle threshold", () => {
727+
expect(
728+
shouldWarnCodexThreadLifecycleTimingSummary(
729+
{
730+
totalMs: 9,
731+
spans: [{ name: "thread-start-request", durationMs: 10, elapsedMs: 10 }],
732+
},
733+
{ totalThresholdMs: 50, stageThresholdMs: 10 },
734+
),
735+
).toBe(true);
736+
expect(
737+
shouldWarnCodexThreadLifecycleTimingSummary(
738+
{
739+
totalMs: 50,
740+
spans: [{ name: "thread-start-request", durationMs: 1, elapsedMs: 1 }],
741+
},
742+
{ totalThresholdMs: 50, stageThresholdMs: 10 },
743+
),
744+
).toBe(true);
745+
});
746+
747+
it("emits a trace stage summary when starting a new thread with trace enabled", async () => {
748+
const sessionFile = path.join(tempDir, "session.jsonl");
749+
const workspaceDir = path.join(tempDir, "workspace");
750+
let nowMs = 0;
751+
const log = createTimingLogger(true);
752+
const request = vi.fn(async (method: string) => {
753+
if (method === "thread/start") {
754+
nowMs += 17;
755+
return threadStartResult("thread-started");
756+
}
757+
throw new Error(`unexpected method: ${method}`);
758+
});
759+
760+
await startOrResumeThread({
761+
client: { request } as never,
762+
params: createThreadLifecycleParams(sessionFile, workspaceDir),
763+
cwd: workspaceDir,
764+
dynamicTools: [],
765+
appServer: createThreadLifecycleAppServerOptions(),
766+
timing: {
767+
enabled: true,
768+
now: () => nowMs,
769+
log,
770+
totalThresholdMs: 1_000,
771+
stageThresholdMs: 1_000,
772+
},
773+
});
774+
775+
const message = expectSingleLogMessage(log, "trace");
776+
expect(log.warn).not.toHaveBeenCalled();
777+
expect(message).toContain("action=started");
778+
expect(message).toContain("thread-start-request:17ms@17ms");
779+
expect(message).toContain("thread-ready:0ms@17ms");
780+
});
781+
782+
it("emits a trace stage summary when resuming an existing thread", async () => {
783+
const sessionFile = path.join(tempDir, "session.jsonl");
784+
const workspaceDir = path.join(tempDir, "workspace");
785+
let nowMs = 0;
786+
const log = createTimingLogger(true);
787+
const request = vi.fn(async (method: string) => {
788+
if (method === "thread/start") {
789+
return threadStartResult("thread-existing");
790+
}
791+
if (method === "thread/resume") {
792+
nowMs += 9;
793+
return threadStartResult("thread-existing");
794+
}
795+
throw new Error(`unexpected method: ${method}`);
796+
});
797+
const commonParams = {
798+
client: { request } as never,
799+
params: createThreadLifecycleParams(sessionFile, workspaceDir),
800+
cwd: workspaceDir,
801+
dynamicTools: [],
802+
appServer: createThreadLifecycleAppServerOptions(),
803+
};
804+
805+
await startOrResumeThread({
806+
...commonParams,
807+
timing: {
808+
enabled: true,
809+
now: () => nowMs,
810+
log: createTimingLogger(false),
811+
},
812+
});
813+
await startOrResumeThread({
814+
...commonParams,
815+
timing: {
816+
enabled: true,
817+
now: () => nowMs,
818+
log,
819+
totalThresholdMs: 1_000,
820+
stageThresholdMs: 1_000,
821+
},
822+
});
823+
824+
const message = expectSingleLogMessage(log, "trace");
825+
expect(message).toContain("action=resumed");
826+
expect(message).toContain("thread-resume-request:9ms@9ms");
827+
});
828+
829+
it("warns on slow start even when trace logging is disabled", async () => {
830+
const sessionFile = path.join(tempDir, "session.jsonl");
831+
const workspaceDir = path.join(tempDir, "workspace");
832+
let nowMs = 0;
833+
const log = createTimingLogger(false);
834+
const request = vi.fn(async (method: string) => {
835+
if (method === "thread/start") {
836+
nowMs += 25;
837+
return threadStartResult("thread-slow");
838+
}
839+
throw new Error(`unexpected method: ${method}`);
840+
});
841+
842+
await startOrResumeThread({
843+
client: { request } as never,
844+
params: createThreadLifecycleParams(sessionFile, workspaceDir),
845+
cwd: workspaceDir,
846+
dynamicTools: [],
847+
appServer: createThreadLifecycleAppServerOptions(),
848+
timing: {
849+
enabled: true,
850+
now: () => nowMs,
851+
log,
852+
totalThresholdMs: 10,
853+
stageThresholdMs: 10,
854+
},
855+
});
856+
857+
const message = expectSingleLogMessage(log, "warn");
858+
expect(log.trace).not.toHaveBeenCalled();
859+
expect(message).toContain("action=started");
860+
expect(message).toContain("thread-start-request:25ms@25ms");
861+
});
862+
});
863+
589864
describe("resolveReasoningEffort (#71946)", () => {
590865
describe("modern Codex models (none/low/medium/high/xhigh enum)", () => {
591866
it.each(["gpt-5.5", "gpt-5.4", "gpt-5.4-mini", "gpt-5.3-codex-spark"] as const)(

0 commit comments

Comments
 (0)