fix: add cli turn output digests

This commit is contained in:
Rajvardhan Patil
2026-05-12 18:08:14 +05:30
committed by Peter Steinberger
parent 628104662b
commit d0ea9667ee
5 changed files with 70 additions and 27 deletions

View File

@@ -1,5 +1,6 @@
import { afterEach, beforeAll, beforeEach, describe, expect, it, vi } from "vitest";
import { SILENT_REPLY_TOKEN } from "../auto-reply/tokens.js";
import { cliBackendLog } from "./cli-runner/log.js";
// vi.mock factories are hoisted above imports, so any references inside them
// must come from vi.hoisted() so they exist at hoist time (otherwise they'd
@@ -114,6 +115,7 @@ afterEach(() => {
describe("runCliAgent cron before_agent_reply seam", () => {
it("lets before_agent_reply claim cron runs before the CLI subprocess is invoked", async () => {
const logInfoSpy = vi.spyOn(cliBackendLog, "info").mockImplementation(() => undefined);
hasHooksMock.mockImplementation((hookName) => hookName === "before_agent_reply");
runBeforeAgentReplyMock.mockResolvedValue({
handled: true,
@@ -121,30 +123,43 @@ describe("runCliAgent cron before_agent_reply seam", () => {
});
const onExecutionPhase = vi.fn();
const result = await runCliAgent({
...baseRunParams,
trigger: "cron",
jobId: "cron-job-123",
onExecutionPhase,
});
try {
const result = await runCliAgent({
...baseRunParams,
trigger: "cron",
jobId: "cron-job-123",
onExecutionPhase,
});
expect(runBeforeAgentReplyMock).toHaveBeenCalledTimes(1);
expect(onExecutionPhase).toHaveBeenCalledWith({
phase: "before_agent_reply",
provider: baseRunParams.provider,
model: baseRunParams.model,
});
const [event, context] = runBeforeAgentReplyMock.mock.calls.at(0) ?? [];
expect(event).toEqual({ cleanedBody: baseRunParams.prompt });
const hookContext = context as Record<string, unknown> | undefined;
expect(hookContext?.jobId).toBe("cron-job-123");
expect(hookContext?.agentId).toBe(baseRunParams.agentId);
expect(hookContext?.sessionId).toBe(baseRunParams.sessionId);
expect(hookContext?.sessionKey).toBe(baseRunParams.sessionKey);
expect(hookContext?.workspaceDir).toBe(baseRunParams.workspaceDir);
expect(hookContext?.trigger).toBe("cron");
expect(executePreparedCliRunMock).not.toHaveBeenCalled();
expect(result.payloads?.[0]?.text).toBe("dreaming claimed via cli runner");
expect(runBeforeAgentReplyMock).toHaveBeenCalledTimes(1);
expect(onExecutionPhase).toHaveBeenCalledWith({
phase: "before_agent_reply",
provider: baseRunParams.provider,
model: baseRunParams.model,
});
const [event, context] = runBeforeAgentReplyMock.mock.calls.at(0) ?? [];
expect(event).toEqual({ cleanedBody: baseRunParams.prompt });
const hookContext = context as Record<string, unknown> | undefined;
expect(hookContext?.jobId).toBe("cron-job-123");
expect(hookContext?.agentId).toBe(baseRunParams.agentId);
expect(hookContext?.sessionId).toBe(baseRunParams.sessionId);
expect(hookContext?.sessionKey).toBe(baseRunParams.sessionKey);
expect(hookContext?.workspaceDir).toBe(baseRunParams.workspaceDir);
expect(hookContext?.trigger).toBe("cron");
expect(executePreparedCliRunMock).not.toHaveBeenCalled();
expect(result.payloads?.[0]?.text).toBe("dreaming claimed via cli runner");
const syntheticTurnLog = logInfoSpy.mock.calls
.map(([message]) => message)
.find((message) => message.startsWith("cli synthetic turn:"));
expect(syntheticTurnLog).toContain("provider=codex-cli");
expect(syntheticTurnLog).toContain("model=<synthetic>");
expect(syntheticTurnLog).toContain("requestedModel=gpt-5.5");
expect(syntheticTurnLog).toContain("outBytes=31 outHash=96317e453543");
expect(syntheticTurnLog).not.toContain("dreaming claimed via cli runner");
} finally {
logInfoSpy.mockRestore();
}
});
it("does not run prepareCliRunContext when the cron hook claims (no resource allocation, no leak)", async () => {

View File

@@ -39,6 +39,7 @@ import {
executePreparedCliRun,
} from "./cli-runner/execute.js";
import { buildSystemPrompt } from "./cli-runner/helpers.js";
import { cliBackendLog, formatCliBackendOutputDigest } from "./cli-runner/log.js";
import { setCliRunnerPrepareTestDeps } from "./cli-runner/prepare.js";
import type { PreparedCliRunContext } from "./cli-runner/types.js";
import { createClaudeApiErrorFixture } from "./test-helpers/claude-api-error-fixture.js";
@@ -261,6 +262,11 @@ async function withTempOpenClawHome(run: (home: string) => Promise<void>): Promi
}
describe("runCliAgent spawn path", () => {
it("formats output digests without logging response content", () => {
expect(formatCliBackendOutputDigest("one")).toBe("outBytes=3 outHash=7692c3ad3540");
expect(formatCliBackendOutputDigest("∑")).toBe("outBytes=3 outHash=be27c7179a61");
});
it("formats redacted CLI resume diagnostics without exposing raw session ids", () => {
const logLine = buildCliExecLogLine({
provider: "claude-cli",
@@ -890,6 +896,7 @@ describe("runCliAgent spawn path", () => {
});
it("reuses a Claude live session process across turns", async () => {
const logInfoSpy = vi.spyOn(cliBackendLog, "info").mockImplementation(() => undefined);
const agentEvents: unknown[] = [];
const stop = onAgentEvent((evt) => {
if (evt.stream === "assistant") {
@@ -988,7 +995,16 @@ describe("runCliAgent spawn path", () => {
{ text: "one", delta: "one" },
{ text: "two", delta: "two" },
]);
const turnLogs = logInfoSpy.mock.calls
.map(([message]) => message)
.filter((message) => message.startsWith("claude live session turn:"));
expect(turnLogs).toHaveLength(2);
expect(turnLogs[0]).toContain("outBytes=3 outHash=7692c3ad3540");
expect(turnLogs[1]).toContain("outBytes=3 outHash=3fc4ccfe7458");
expect(turnLogs.join("\n")).not.toContain("one");
expect(turnLogs.join("\n")).not.toContain("two");
} finally {
logInfoSpy.mockRestore();
stop();
}
});

View File

@@ -5,6 +5,7 @@ import { createSubsystemLogger } from "../logging/subsystem.js";
import { buildAgentHookContextChannelFields } from "../plugins/hook-agent-context.js";
import { resolveBlockMessage } from "../plugins/hook-decision-types.js";
import { getGlobalHookRunner } from "../plugins/hook-runner-global.js";
import { cliBackendLog, formatCliBackendOutputDigest } from "./cli-runner/log.js";
import {
loadCliSessionContextEngineMessages,
loadCliSessionHistoryMessages,
@@ -238,6 +239,10 @@ export async function runCliAgent(params: RunCliAgentParams): Promise<EmbeddedAg
hookContext,
);
if (hookResult?.handled) {
const finalText = hookResult.reply?.text ?? SILENT_REPLY_TOKEN;
cliBackendLog.info(
`cli synthetic turn: provider=${params.provider} model=<synthetic> requestedModel=${params.model ?? ""} durationMs=${Date.now() - startedAt} ${formatCliBackendOutputDigest(finalText)}`,
);
return {
payloads: buildHandledReplyPayloads(hookResult.reply),
meta: {
@@ -247,8 +252,8 @@ export async function runCliAgent(params: RunCliAgentParams): Promise<EmbeddedAg
provider: params.provider,
model: params.model ?? "",
},
finalAssistantVisibleText: hookResult.reply?.text ?? SILENT_REPLY_TOKEN,
finalAssistantRawText: hookResult.reply?.text ?? SILENT_REPLY_TOKEN,
finalAssistantVisibleText: finalText,
finalAssistantRawText: finalText,
},
};
}

View File

@@ -29,7 +29,7 @@ import {
} from "../cli-output.js";
import { classifyFailoverReason } from "../embedded-agent-helpers.js";
import { FailoverError, resolveFailoverStatus } from "../failover-error.js";
import { cliBackendLog } from "./log.js";
import { cliBackendLog, formatCliBackendOutputDigest } from "./log.js";
import type { PreparedCliRunContext } from "./types.js";
type ProcessSupervisor = ReturnType<
@@ -376,7 +376,7 @@ function finishTurn(session: ClaudeLiveSession, output: CliOutput): void {
return;
}
cliBackendLog.info(
`claude live session turn: provider=${session.providerId} model=${session.modelId} durationMs=${Date.now() - turn.startedAtMs} rawLines=${turn.rawLines.length}`,
`claude live session turn: provider=${session.providerId} model=${session.modelId} durationMs=${Date.now() - turn.startedAtMs} rawLines=${turn.rawLines.length} ${formatCliBackendOutputDigest(output.text)}`,
);
completeActiveClaudeLiveTools(turn);
clearTurnTimers(turn);

View File

@@ -1,5 +1,12 @@
import crypto from "node:crypto";
import { createSubsystemLogger } from "../../logging/subsystem.js";
export const cliBackendLog = createSubsystemLogger("agent/cli-backend");
export const CLI_BACKEND_LOG_OUTPUT_ENV = "OPENCLAW_CLI_BACKEND_LOG_OUTPUT";
export const LEGACY_CLAUDE_CLI_LOG_OUTPUT_ENV = "OPENCLAW_CLAUDE_CLI_LOG_OUTPUT";
export function formatCliBackendOutputDigest(text: string): string {
const outBytes = Buffer.byteLength(text, "utf8");
const outHash = crypto.createHash("sha256").update(text).digest("hex").slice(0, 12);
return `outBytes=${outBytes} outHash=${outHash}`;
}