diff --git a/docs/concepts/compaction.md b/docs/concepts/compaction.md index 46bb5067809..ea6efe11ddd 100644 --- a/docs/concepts/compaction.md +++ b/docs/concepts/compaction.md @@ -24,6 +24,7 @@ Auto-compaction is on by default. It runs when the session nears the context lim You will see: +- `embedded run auto-compaction start` / `complete` in normal Gateway logs. - `🧹 Auto-compaction complete` in verbose mode. - `/status` showing `🧹 Compactions: `. diff --git a/docs/reference/session-management-compaction.md b/docs/reference/session-management-compaction.md index 1c93553cf2b..0725f7f59d6 100644 --- a/docs/reference/session-management-compaction.md +++ b/docs/reference/session-management-compaction.md @@ -376,6 +376,7 @@ You can observe compaction and session state via: - `/status` (in any chat session) - `openclaw status` (CLI) - `openclaw sessions` / `sessions --json` +- Gateway logs (`pnpm gateway:watch` or `openclaw logs --follow`): `embedded run auto-compaction start` + `complete` - Verbose mode: `🧹 Auto-compaction complete` + compaction count --- diff --git a/src/agents/openclaw-owned-tool-runtime-contract.test.ts b/src/agents/openclaw-owned-tool-runtime-contract.test.ts index 23e8cf2dbc7..5796f234bd6 100644 --- a/src/agents/openclaw-owned-tool-runtime-contract.test.ts +++ b/src/agents/openclaw-owned-tool-runtime-contract.test.ts @@ -47,7 +47,7 @@ function createToolHandlerCtx(): ToolHandlerContext { messagingToolSentTargets: [] as MessagingToolSend[], successfulCronAdds: 0, }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, flushBlockReplyBuffer: vi.fn(), shouldEmitToolResult: () => false, shouldEmitToolOutput: () => false, diff --git a/src/agents/pi-embedded-subscribe.handlers.compaction.test.ts b/src/agents/pi-embedded-subscribe.handlers.compaction.test.ts index 3079afeb09f..5534b4c72e8 100644 --- a/src/agents/pi-embedded-subscribe.handlers.compaction.test.ts +++ b/src/agents/pi-embedded-subscribe.handlers.compaction.test.ts @@ -10,6 +10,7 @@ import { } from "./pi-embedded-subscribe.compaction-test-helpers.js"; import { handleCompactionEnd, + handleCompactionStart, reconcileSessionStoreCompactionCountAfterSuccess, } from "./pi-embedded-subscribe.handlers.compaction.js"; import type { EmbeddedPiSubscribeContext } from "./pi-embedded-subscribe.handlers.types.js"; @@ -19,6 +20,7 @@ function createCompactionContext(params: { sessionKey: string; agentId?: string; initialCount: number; + info?: (message: string, meta?: Record) => void; }): EmbeddedPiSubscribeContext { let compactionCount = params.initialCount; return { @@ -37,6 +39,7 @@ function createCompactionContext(params: { } as never, log: { debug: vi.fn(), + info: params.info ?? vi.fn(), warn: vi.fn(), }, ensureCompactionPromise: vi.fn(), @@ -103,6 +106,168 @@ describe("reconcileSessionStoreCompactionCountAfterSuccess", () => { }); }); +describe("compaction lifecycle logging", () => { + it("logs lifecycle events at info level for gateway watch visibility", async () => { + const tmp = await fs.mkdtemp(path.join(os.tmpdir(), "openclaw-compaction-log-")); + const storePath = path.join(tmp, "sessions.json"); + const sessionKey = "main"; + await seedSessionStore({ + storePath, + sessionKey, + compactionCount: 0, + }); + const info = vi.fn(); + const ctx = createCompactionContext({ + storePath, + sessionKey, + initialCount: 0, + info, + }); + + handleCompactionStart(ctx, { + type: "compaction_start", + reason: "threshold", + }); + handleCompactionEnd(ctx, { + type: "compaction_end", + reason: "threshold", + result: { kept: 12 }, + willRetry: false, + aborted: false, + }); + + expect(info).toHaveBeenNthCalledWith( + 1, + "embedded run auto-compaction start", + expect.objectContaining({ + event: "embedded_run_compaction_start", + reason: "threshold", + runId: "run-test", + consoleMessage: "embedded run auto-compaction start: runId=run-test reason=threshold", + }), + ); + expect(info).toHaveBeenNthCalledWith( + 2, + "embedded run auto-compaction complete", + expect.objectContaining({ + event: "embedded_run_compaction_end", + reason: "threshold", + runId: "run-test", + completed: true, + compactionCount: 1, + consoleMessage: + "embedded run auto-compaction complete: runId=run-test reason=threshold compactionCount=1 willRetry=false", + }), + ); + }); + + it("logs manual compaction as incomplete when no result is produced", async () => { + const tmp = await fs.mkdtemp(path.join(os.tmpdir(), "openclaw-compaction-incomplete-log-")); + const storePath = path.join(tmp, "sessions.json"); + const sessionKey = "main"; + await seedSessionStore({ + storePath, + sessionKey, + compactionCount: 0, + }); + const info = vi.fn(); + const ctx = createCompactionContext({ + storePath, + sessionKey, + initialCount: 0, + info, + }); + + handleCompactionStart(ctx, { + type: "compaction_start", + reason: "manual", + }); + handleCompactionEnd(ctx, { + type: "compaction_end", + reason: "manual", + result: undefined, + willRetry: false, + aborted: false, + }); + + expect(info).toHaveBeenNthCalledWith( + 1, + "embedded run manual compaction start", + expect.objectContaining({ + event: "embedded_run_compaction_start", + reason: "manual", + runId: "run-test", + consoleMessage: "embedded run manual compaction start: runId=run-test reason=manual", + }), + ); + expect(info).toHaveBeenNthCalledWith( + 2, + "embedded run manual compaction incomplete", + expect.objectContaining({ + event: "embedded_run_compaction_end", + reason: "manual", + runId: "run-test", + completed: false, + aborted: false, + consoleMessage: + "embedded run manual compaction incomplete: runId=run-test reason=manual aborted=false willRetry=false", + }), + ); + }); + + it("defaults legacy synthetic compaction events to threshold logs", async () => { + const tmp = await fs.mkdtemp(path.join(os.tmpdir(), "openclaw-compaction-legacy-log-")); + const storePath = path.join(tmp, "sessions.json"); + const sessionKey = "main"; + await seedSessionStore({ + storePath, + sessionKey, + compactionCount: 0, + }); + const info = vi.fn(); + const ctx = createCompactionContext({ + storePath, + sessionKey, + initialCount: 0, + info, + }); + + handleCompactionStart(ctx, { + type: "compaction_start", + }); + handleCompactionEnd(ctx, { + type: "compaction_end", + result: { kept: 12 }, + willRetry: false, + aborted: false, + }); + + expect(info).toHaveBeenNthCalledWith( + 1, + "embedded run auto-compaction start", + expect.objectContaining({ + event: "embedded_run_compaction_start", + reason: "threshold", + runId: "run-test", + consoleMessage: "embedded run auto-compaction start: runId=run-test reason=threshold", + }), + ); + expect(info).toHaveBeenNthCalledWith( + 2, + "embedded run auto-compaction complete", + expect.objectContaining({ + event: "embedded_run_compaction_end", + reason: "threshold", + runId: "run-test", + completed: true, + compactionCount: 1, + consoleMessage: + "embedded run auto-compaction complete: runId=run-test reason=threshold compactionCount=1 willRetry=false", + }), + ); + }); +}); + describe("handleCompactionEnd", () => { it("reconciles the session store after a successful compaction end event", async () => { const tmp = await fs.mkdtemp(path.join(os.tmpdir(), "openclaw-compaction-handler-")); @@ -122,10 +287,11 @@ describe("handleCompactionEnd", () => { handleCompactionEnd(ctx, { type: "compaction_end", + reason: "threshold", result: { kept: 12 }, willRetry: false, aborted: false, - } as never); + }); await waitForCompactionCount({ storePath, diff --git a/src/agents/pi-embedded-subscribe.handlers.compaction.ts b/src/agents/pi-embedded-subscribe.handlers.compaction.ts index 4d7106d094b..1a8712f1c37 100644 --- a/src/agents/pi-embedded-subscribe.handlers.compaction.ts +++ b/src/agents/pi-embedded-subscribe.handlers.compaction.ts @@ -1,14 +1,48 @@ -import type { AgentEvent } from "@earendil-works/pi-agent-core"; +import type { AgentSessionEvent } from "@earendil-works/pi-coding-agent"; import { emitAgentEvent } from "../infra/agent-events.js"; import { getGlobalHookRunner } from "../plugins/hook-runner-global.js"; import type { EmbeddedPiSubscribeContext } from "./pi-embedded-subscribe.handlers.types.js"; import { makeZeroUsageSnapshot } from "./usage.js"; -export function handleCompactionStart(ctx: EmbeddedPiSubscribeContext) { +type SessionCompactionStartEvent = Extract; +type SessionCompactionEndEvent = Extract; +type CompactionReason = SessionCompactionStartEvent["reason"]; + +type CompactionStartEvent = SessionCompactionStartEvent | { + type: "compaction_start"; + reason?: unknown; +}; + +type CompactionEndEvent = SessionCompactionEndEvent | { + type: "compaction_end"; + reason?: unknown; + willRetry?: unknown; + result?: unknown; + aborted?: unknown; +}; + +function normalizeCompactionReason(reason: unknown): CompactionReason { + return reason === "manual" || reason === "threshold" || reason === "overflow" + ? reason + : "threshold"; +} + +function compactionLogKind(reason: CompactionReason): string { + return reason === "manual" ? "manual compaction" : "auto-compaction"; +} + +export function handleCompactionStart(ctx: EmbeddedPiSubscribeContext, evt: CompactionStartEvent) { + const reason = normalizeCompactionReason(evt.reason); + const kind = compactionLogKind(reason); ctx.state.compactionInFlight = true; ctx.state.livenessState = "paused"; ctx.ensureCompactionPromise(); - ctx.log.debug(`embedded run compaction start: runId=${ctx.params.runId}`); + ctx.log.info(`embedded run ${kind} start`, { + event: "embedded_run_compaction_start", + runId: ctx.params.runId, + reason, + consoleMessage: `embedded run ${kind} start: runId=${ctx.params.runId} reason=${reason}`, + }); emitAgentEvent({ runId: ctx.params.runId, stream: "compaction", @@ -39,10 +73,9 @@ export function handleCompactionStart(ctx: EmbeddedPiSubscribeContext) { } } -export function handleCompactionEnd( - ctx: EmbeddedPiSubscribeContext, - evt: AgentEvent & { willRetry?: unknown; result?: unknown; aborted?: unknown }, -) { +export function handleCompactionEnd(ctx: EmbeddedPiSubscribeContext, evt: CompactionEndEvent) { + const reason = normalizeCompactionReason(evt.reason); + const kind = compactionLogKind(reason); ctx.state.compactionInFlight = false; const willRetry = Boolean(evt.willRetry); // Increment counter whenever compaction actually produced a result, @@ -59,6 +92,15 @@ export function handleCompactionEnd( : undefined; ctx.noteCompactionTokensAfter(tokensAfter); const observedCompactionCount = ctx.getCompactionCount(); + ctx.log.info(`embedded run ${kind} complete`, { + event: "embedded_run_compaction_end", + runId: ctx.params.runId, + reason, + completed: true, + willRetry, + compactionCount: observedCompactionCount, + consoleMessage: `embedded run ${kind} complete: runId=${ctx.params.runId} reason=${reason} compactionCount=${observedCompactionCount} willRetry=${willRetry}`, + }); void reconcileSessionStoreCompactionCountAfterSuccess({ sessionKey: ctx.params.sessionKey, agentId: ctx.params.agentId, @@ -79,6 +121,17 @@ export function handleCompactionEnd( ctx.maybeResolveCompactionWait(); clearStaleAssistantUsageOnSessionMessages(ctx); } + if (!hasResult || wasAborted) { + ctx.log.info(`embedded run ${kind} incomplete`, { + event: "embedded_run_compaction_end", + runId: ctx.params.runId, + reason, + completed: false, + willRetry, + aborted: wasAborted, + consoleMessage: `embedded run ${kind} incomplete: runId=${ctx.params.runId} reason=${reason} aborted=${wasAborted} willRetry=${willRetry}`, + }); + } emitAgentEvent({ runId: ctx.params.runId, stream: "compaction", diff --git a/src/agents/pi-embedded-subscribe.handlers.messages.test.ts b/src/agents/pi-embedded-subscribe.handlers.messages.test.ts index 3fb9c20fc76..d6bac569ba2 100644 --- a/src/agents/pi-embedded-subscribe.handlers.messages.test.ts +++ b/src/agents/pi-embedded-subscribe.handlers.messages.test.ts @@ -125,7 +125,7 @@ function createMessageEndContext( noteLastAssistant: vi.fn(), recordAssistantUsage: vi.fn(), commitAssistantUsage: vi.fn(), - log: { debug: vi.fn(), warn: params.warn ?? vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: params.warn ?? vi.fn() }, builtinToolNames: params.builtinToolNames, stripBlockTags: (text: string) => text, finalizeAssistantTexts: params.finalizeAssistantTexts ?? vi.fn(), diff --git a/src/agents/pi-embedded-subscribe.handlers.tools.media.test.ts b/src/agents/pi-embedded-subscribe.handlers.tools.media.test.ts index 2e93720f96a..a5e410619ab 100644 --- a/src/agents/pi-embedded-subscribe.handlers.tools.media.test.ts +++ b/src/agents/pi-embedded-subscribe.handlers.tools.media.test.ts @@ -40,7 +40,7 @@ function createMockContext(overrides?: { deterministicApprovalPromptPending: false, deterministicApprovalPromptSent: false, }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, builtinToolNames: overrides?.builtinToolNames, shouldEmitToolResult: vi.fn(() => false), shouldEmitToolOutput: vi.fn(() => overrides?.shouldEmitToolOutput ?? false), diff --git a/src/agents/pi-embedded-subscribe.handlers.tools.test.ts b/src/agents/pi-embedded-subscribe.handlers.tools.test.ts index f8de2f0ab73..2cb710d204d 100644 --- a/src/agents/pi-embedded-subscribe.handlers.tools.test.ts +++ b/src/agents/pi-embedded-subscribe.handlers.tools.test.ts @@ -41,6 +41,7 @@ function createTestContext(): { hookRunner: undefined, log: { debug: vi.fn(), + info: vi.fn(), warn, }, state: { diff --git a/src/agents/pi-embedded-subscribe.handlers.ts b/src/agents/pi-embedded-subscribe.handlers.ts index 09138d660c8..b22a76d8fd2 100644 --- a/src/agents/pi-embedded-subscribe.handlers.ts +++ b/src/agents/pi-embedded-subscribe.handlers.ts @@ -115,12 +115,12 @@ export function createEmbeddedPiSessionEventHandler(ctx: EmbeddedPiSubscribeCont return; case "compaction_start": scheduleEvent(evt, () => { - handleCompactionStart(ctx); + handleCompactionStart(ctx, evt); }); return; case "compaction_end": scheduleEvent(evt, () => { - handleCompactionEnd(ctx, evt as never); + handleCompactionEnd(ctx, evt); }); return; case "agent_end": diff --git a/src/agents/pi-embedded-subscribe.handlers.types.ts b/src/agents/pi-embedded-subscribe.handlers.types.ts index 90d508b2901..1b17b3d88e9 100644 --- a/src/agents/pi-embedded-subscribe.handlers.types.ts +++ b/src/agents/pi-embedded-subscribe.handlers.types.ts @@ -1,4 +1,5 @@ -import type { AgentEvent, AgentMessage } from "@earendil-works/pi-agent-core"; +import type { AgentMessage } from "@earendil-works/pi-agent-core"; +import type { AgentSessionEvent } from "@earendil-works/pi-coding-agent"; import type { HeartbeatToolResponse } from "../auto-reply/heartbeat-tool-response.js"; import type { ReplyDirectiveParseResult } from "../auto-reply/reply/reply-directives.js"; import type { ReasoningLevel } from "../auto-reply/thinking.js"; @@ -18,6 +19,7 @@ import type { NormalizedUsage } from "./usage.js"; type EmbeddedSubscribeLogger = { debug: (message: string, meta?: Record) => void; + info: (message: string, meta?: Record) => void; warn: (message: string, meta?: Record) => void; }; @@ -237,6 +239,6 @@ export type ToolHandlerContext = { }; export type EmbeddedPiSubscribeEvent = - | AgentEvent + | AgentSessionEvent | { type: string; [k: string]: unknown } | { type: "message_start"; message: AgentMessage }; diff --git a/src/agents/pi-tool-definition-adapter.after-tool-call.fires-once.test.ts b/src/agents/pi-tool-definition-adapter.after-tool-call.fires-once.test.ts index a2518b98f6f..8af72da8837 100644 --- a/src/agents/pi-tool-definition-adapter.after-tool-call.fires-once.test.ts +++ b/src/agents/pi-tool-definition-adapter.after-tool-call.fires-once.test.ts @@ -73,7 +73,7 @@ function createToolHandlerCtx() { ...createBaseToolHandlerState(), successfulCronAdds: 0, }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, flushBlockReplyBuffer: vi.fn(), shouldEmitToolResult: () => false, shouldEmitToolOutput: () => false, diff --git a/src/plugins/wired-hooks-after-tool-call.e2e.test.ts b/src/plugins/wired-hooks-after-tool-call.e2e.test.ts index 840c25904f9..f806f80eb77 100644 --- a/src/plugins/wired-hooks-after-tool-call.e2e.test.ts +++ b/src/plugins/wired-hooks-after-tool-call.e2e.test.ts @@ -43,7 +43,7 @@ function createToolHandlerCtx(params: { state: { ...createBaseToolHandlerState(), }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, flushBlockReplyBuffer: vi.fn(), shouldEmitToolResult: () => false, shouldEmitToolOutput: () => false, diff --git a/src/plugins/wired-hooks-compaction.test.ts b/src/plugins/wired-hooks-compaction.test.ts index 68361f079f2..c84177794d5 100644 --- a/src/plugins/wired-hooks-compaction.test.ts +++ b/src/plugins/wired-hooks-compaction.test.ts @@ -55,7 +55,7 @@ describe("compaction hook wiring", () => { }, }, state: { compactionInFlight: true }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, maybeResolveCompactionWait: vi.fn(), incrementCompactionCount: vi.fn(), getCompactionCount: () => params.compactionCount ?? 0, @@ -136,12 +136,12 @@ describe("compaction hook wiring", () => { onAgentEvent: vi.fn(), }, state: { compactionInFlight: false }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, incrementCompactionCount: vi.fn(), ensureCompactionPromise: vi.fn(), }; - handleCompactionStart(ctx as never); + handleCompactionStart(ctx as never, { type: "compaction_start", reason: "threshold" }); expect(hookMocks.runner.runBeforeCompaction).toHaveBeenCalledTimes(1); expectCompactionEvent({ @@ -253,7 +253,7 @@ describe("compaction hook wiring", () => { const ctx = { params: { runId: "r4", session: { messages } }, state: { compactionInFlight: true }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, maybeResolveCompactionWait: vi.fn(), getCompactionCount: () => 1, incrementCompactionCount: vi.fn(), @@ -281,7 +281,7 @@ describe("compaction hook wiring", () => { const ctx = { params: { runId: "r5", session: { messages } }, state: { compactionInFlight: true }, - log: { debug: vi.fn(), warn: vi.fn() }, + log: { debug: vi.fn(), info: vi.fn(), warn: vi.fn() }, noteCompactionRetry: vi.fn(), resetForCompactionRetry: vi.fn(), getCompactionCount: () => 0,