From 6bddc9d044c8083a9397bd4ffcf89087eead8e1a Mon Sep 17 00:00:00 2001 From: Haoqing Wang <78337154+hqhq1025@users.noreply.github.com> Date: Sun, 26 Jul 2026 02:46:29 +0800 Subject: [PATCH] fix(cli): stop internal agent events from leaking into chat as raw JSON (#1165) * fix(cli): drop unknown SDK message types instead of passing them through The SDK-to-log converter's switch had a fail-open default that stamped any unrecognized SDK message with transcript base fields (parentUuid/sessionId/ userType) and forwarded it. Claude Code emits a tool_progress heartbeat every 30s for long-running tools, so a single slow Bash call flooded the chat: the web normalizer matches no known shape for those records and falls back to rendering the raw envelope as message text. Gate the switch on an explicit allowlist instead, bailing before the uuid is allocated so a dropped event cannot advance sidechain/parent tracking -- the heartbeats share one parent_tool_use_id and were overwriting the pointer a subagent's next real message parents to. This matches the local launcher, which already enforces the same allowlist via RawJSONLinesSchema.safeParse. The default branch stays as a fail-closed guard so adding a type to the allowlist without a matching case drops the message rather than leaking it. * fix(cli): re-check reassembled text for internal event JSON at flush boundary isInternalEventJson was only applied per incoming chunk. In delta mode (OpenCode) every chunk is a fragment, so none of them parses as JSON on its own and the filter never fires; the pieces accumulate and flushText emits the reassembled envelope verbatim. The dedupe path has the same hole whenever two chunks share no overlap. Check again in flushText, which is the first point the complete text exists, and tolerate surrounding whitespace so an envelope preceded by a newline is not waved through by the leading-'{' fast path. Genuine assistant output that happens to be JSON is unaffected: the matcher still requires the specific { type: 'output', data: { parentUuid, sessionId, userType } } envelope shape. * fix(cli): fail closed on unrecognized agent message in converter convertAgentMessage's exhaustiveness default returned the message object itself at runtime. The never binding makes the branch unreachable today, but every caller forwards a non-null result straight into the chat stream, so the failure mode if it were ever reached is a raw object on screen. Keep the compile-time check, return null at runtime. * test(cli): cover command_lifecycle, a second unknown type seen leaking Observed in the same session after tool_progress. The allowlist already covered it with no code change, which is the argument for gating on known types rather than adding a case per offender. --- .../backends/acp/AcpMessageHandler.test.ts | 78 ++++++++++++ .../agent/backends/acp/AcpMessageHandler.ts | 11 ++ cli/src/agent/internalEventFilter.ts | 10 +- cli/src/agent/messageConverter.test.ts | 6 + cli/src/agent/messageConverter.ts | 9 +- .../claude/utils/sdkToLogConverter.test.ts | 118 ++++++++++++++++++ cli/src/claude/utils/sdkToLogConverter.ts | 43 ++++++- 7 files changed, 264 insertions(+), 11 deletions(-) diff --git a/cli/src/agent/backends/acp/AcpMessageHandler.test.ts b/cli/src/agent/backends/acp/AcpMessageHandler.test.ts index 7cb268e1..74e3cf13 100644 --- a/cli/src/agent/backends/acp/AcpMessageHandler.test.ts +++ b/cli/src/agent/backends/acp/AcpMessageHandler.test.ts @@ -1067,6 +1067,84 @@ describe('AcpMessageHandler', () => { expect((messages[0] as { text: string }).text).toMatch(/^Claude AI usage limit warning\|/); }); + it('drops a metadata envelope split across delta chunks', () => { + // In delta mode every chunk is a fragment, so no individual chunk ever + // parses as JSON and the per-chunk filter never fires. Only the flush + // boundary sees the reassembled envelope. + const messages: AgentMessage[] = []; + const handler = new AcpMessageHandler( + (message) => messages.push(message), + { textChunkMode: 'delta' } + ); + + const metadataJson = JSON.stringify({ + type: 'output', + data: { + parentUuid: null, + isSidechain: true, + userType: 'external', + sessionId: '5605239b-3ca8-4cf4-bf06-a234f7984f2f', + type: 'tool_progress', + tool_name: 'Bash', + elapsed_time_seconds: 30, + heartbeat: true, + }, + }); + + for (let i = 0; i < metadataJson.length; i += 17) { + handler.handleUpdate({ + sessionUpdate: ACP_SESSION_UPDATE_TYPES.agentMessageChunk, + content: { type: 'text', text: metadataJson.slice(i, i + 17) } + }); + } + + handler.flushText(); + + expect(messages).toEqual([]); + }); + + it('drops a metadata envelope that arrives with leading whitespace', () => { + const messages: AgentMessage[] = []; + const handler = new AcpMessageHandler((message) => messages.push(message)); + + const metadataJson = JSON.stringify({ + type: 'output', + data: { + parentUuid: null, + sessionId: 'session-789', + userType: 'external', + }, + }); + handler.handleUpdate({ + sessionUpdate: ACP_SESSION_UPDATE_TYPES.agentMessageChunk, + content: { type: 'text', text: `\n ${metadataJson}` } + }); + + handler.flushText(); + + expect(messages).toEqual([]); + }); + + it('still emits genuine assistant text that happens to be JSON', () => { + const messages: AgentMessage[] = []; + const handler = new AcpMessageHandler( + (message) => messages.push(message), + { textChunkMode: 'delta' } + ); + + const answer = '{"name":"hapi","version":"0.23.4"}'; + for (const chunk of [answer.slice(0, 10), answer.slice(10)]) { + handler.handleUpdate({ + sessionUpdate: ACP_SESSION_UPDATE_TYPES.agentMessageChunk, + content: { type: 'text', text: chunk } + }); + } + + handler.flushText(); + + expect(messages).toEqual([{ type: 'text', text: answer }]); + }); + it('forwards agent_thought_chunk as a reasoning message after flush', () => { const messages: AgentMessage[] = []; const handler = new AcpMessageHandler((message) => messages.push(message)); diff --git a/cli/src/agent/backends/acp/AcpMessageHandler.ts b/cli/src/agent/backends/acp/AcpMessageHandler.ts index 69240669..e3c01a61 100644 --- a/cli/src/agent/backends/acp/AcpMessageHandler.ts +++ b/cli/src/agent/backends/acp/AcpMessageHandler.ts @@ -419,6 +419,14 @@ export class AcpMessageHandler { * buffer. Callers must treat this as a text-segment boundary: it is * invoked internally before tool_call / plan events and externally at * turn boundaries by AcpSdkBackend. + * + * The internal-event check in `handleUpdate` only sees one chunk at a + * time, so it cannot recognise an envelope that arrived in pieces — in + * `delta` mode (OpenCode) every chunk is a fragment and none of them + * parses as JSON on its own. This flush boundary is the first place the + * reassembled text exists, so it is the only place a split envelope can + * be caught. Re-checking here is what makes the filter complete rather + * than merely likely to fire. */ flushText(): void { if (!this.bufferedText) { @@ -426,6 +434,9 @@ export class AcpMessageHandler { } const text = this.bufferedText; this.bufferedText = ''; + if (isInternalEventJson(text)) { + return; + } this.onMessage({ type: 'text', text }); } diff --git a/cli/src/agent/internalEventFilter.ts b/cli/src/agent/internalEventFilter.ts index 6722227b..6718d457 100644 --- a/cli/src/agent/internalEventFilter.ts +++ b/cli/src/agent/internalEventFilter.ts @@ -8,15 +8,17 @@ * We match on the specific structure rather than a broad type allowlist to * avoid accidentally suppressing legitimate assistant JSON. * - * Only called for text that starts with '{', so the fast-path for normal - * prose has zero overhead. + * Surrounding whitespace is tolerated: the envelope is also checked at the + * text-flush boundary, where it may have been reassembled from chunks that + * carried a leading newline or indentation. */ export function isInternalEventJson(text: string): boolean { - if (text[0] !== '{') return false; + const trimmed = text.trim(); + if (trimmed[0] !== '{') return false; let parsed: unknown; try { - parsed = JSON.parse(text); + parsed = JSON.parse(trimmed); } catch { return false; } diff --git a/cli/src/agent/messageConverter.test.ts b/cli/src/agent/messageConverter.test.ts index 496bd8ce..d32fa523 100644 --- a/cli/src/agent/messageConverter.test.ts +++ b/cli/src/agent/messageConverter.test.ts @@ -106,4 +106,10 @@ describe('convertAgentMessage', () => { } }); }); + it('returns null instead of echoing an unrecognized message shape', () => { + // Unreachable through the type system, but callers forward any non-null + // result straight into the chat stream — so the runtime contract has to + // be fail-closed. + expect(convertAgentMessage({ type: 'not_a_real_type' } as never)).toBeNull(); + }); }); diff --git a/cli/src/agent/messageConverter.ts b/cli/src/agent/messageConverter.ts index 0425ca19..034f7dad 100644 --- a/cli/src/agent/messageConverter.ts +++ b/cli/src/agent/messageConverter.ts @@ -87,8 +87,15 @@ export function convertAgentMessage(message: AgentMessage): CodexMessage | null case 'turn_complete': return null; default: { + // Unreachable while every AgentMessage variant is handled above — + // the `never` binding is what enforces that at compile time. The + // runtime return is deliberately `null` rather than the message + // itself: callers forward a non-null result straight into the chat + // stream, so echoing an unrecognized shape here would put a raw + // object on screen instead of failing closed. const _exhaustive: never = message; - return _exhaustive; + void _exhaustive; + return null; } } } diff --git a/cli/src/claude/utils/sdkToLogConverter.test.ts b/cli/src/claude/utils/sdkToLogConverter.test.ts index 8c4e1cbe..6114480a 100644 --- a/cli/src/claude/utils/sdkToLogConverter.test.ts +++ b/cli/src/claude/utils/sdkToLogConverter.test.ts @@ -923,6 +923,124 @@ describe('SDKToLogConverter', () => { }) }) + describe('Unknown message types', () => { + it('should drop tool_progress heartbeat events instead of passing them through', () => { + const logMessage = converter.convert({ + type: 'tool_progress', + tool_use_id: 'toolu_011qMV3YCgDP89zcjHbC4rd2-heartbeat-0', + tool_name: 'Bash', + parent_tool_use_id: 'toolu_011qMV3YCgDP89zcjHbC4rd2', + elapsed_time_seconds: 30, + heartbeat: true, + session_id: context.sessionId + } as unknown as SDKMessage) + + expect(logMessage).toBeNull() + }) + + it('should drop arbitrary unknown SDK message types', () => { + for (const type of ['stream_event', 'control_response', 'log', 'some_future_event']) { + expect(converter.convert({ type, payload: { foo: 'bar' } } as unknown as SDKMessage)).toBeNull() + } + }) + + it('should drop command_lifecycle events', () => { + // Second unknown type observed leaking in the wild, after + // tool_progress. It needed no code change to cover — which is the + // point of gating on an allowlist rather than naming each offender. + const logMessage = converter.convert({ + type: 'command_lifecycle', + command_uuid: 'a0c15039-fb30-4ba3-bf1b-6afc3196cbeb', + state: 'started', + session_id: context.sessionId + } as unknown as SDKMessage) + + expect(logMessage).toBeNull() + }) + + it('should not break parent chain when an unknown type is dropped', () => { + const user = converter.convert({ + type: 'user', + message: { role: 'user', content: 'hi' } + } as SDKUserMessage) + + converter.convert({ + type: 'tool_progress', + parent_tool_use_id: 'toolu_abc', + heartbeat: true + } as unknown as SDKMessage) + + const assistant = converter.convert({ + type: 'assistant', + message: { role: 'assistant', content: [{ type: 'text', text: 'hello' }] } + } as SDKAssistantMessage) + + expect(assistant!.parentUuid).toBe(user!.uuid) + }) + + it('should not let repeated tool_progress heartbeats hijack sidechain parent tracking', () => { + // A long-running Bash inside a Task subagent emits a tool_progress + // heartbeat every 30s, all sharing the subagent's parent_tool_use_id. + // Converting them would overwrite sidechainLastUUID on every tick, so + // the subagent's next real message would be parented to a heartbeat + // rather than to its own previous message. + const parentToolUseId = 'toolu_011qMV3YCgDP89zcjHbC4rd2' + + const firstSidechainMessage = converter.convert({ + type: 'assistant', + parent_tool_use_id: parentToolUseId, + message: { role: 'assistant', content: [{ type: 'text', text: 'working' }] } + } as unknown as SDKAssistantMessage) + + for (let tick = 0; tick < 3; tick++) { + const heartbeat = converter.convert({ + type: 'tool_progress', + tool_use_id: `${parentToolUseId}-heartbeat-${tick}`, + tool_name: 'Bash', + parent_tool_use_id: parentToolUseId, + elapsed_time_seconds: (tick + 1) * 30, + heartbeat: true, + session_id: context.sessionId + } as unknown as SDKMessage) + + expect(heartbeat).toBeNull() + } + + const nextSidechainMessage = converter.convert({ + type: 'assistant', + parent_tool_use_id: parentToolUseId, + message: { role: 'assistant', content: [{ type: 'text', text: 'done' }] } + } as unknown as SDKAssistantMessage) + + expect(nextSidechainMessage!.isSidechain).toBe(true) + expect(nextSidechainMessage!.parentUuid).toBe(firstSidechainMessage!.uuid) + }) + + it('should still convert every known type', () => { + expect(converter.convert({ + type: 'user', + message: { role: 'user', content: 'hi' } + } as SDKUserMessage)).toBeTruthy() + + expect(converter.convert({ + type: 'assistant', + message: { role: 'assistant', content: [{ type: 'text', text: 'yo' }] } + } as SDKAssistantMessage)).toBeTruthy() + + expect(converter.convert({ + type: 'system', + subtype: 'init', + model: 'claude-opus-4-8' + } as SDKSystemMessage)).toBeTruthy() + + expect(converter.convert({ + type: 'tool_result', + tool_use_id: 'toolu_x', + content: 'done' + } as unknown as SDKMessage)).toBeTruthy() + }) + }) + describe('Convenience function', () => { it('should convert single message without state', () => { const sdkMessage: SDKUserMessage = { diff --git a/cli/src/claude/utils/sdkToLogConverter.ts b/cli/src/claude/utils/sdkToLogConverter.ts index 36ec09cf..7184fc5b 100644 --- a/cli/src/claude/utils/sdkToLogConverter.ts +++ b/cli/src/claude/utils/sdkToLogConverter.ts @@ -14,6 +14,30 @@ import type { } from '@/claude/sdk' import type { RawJSONLines } from '@/claude/types' import type { ClaudePermissionMode } from '@hapi/protocol/types' +import { logger } from '@/lib' + +/** + * SDK message types this converter knows how to turn into a transcript line. + * + * Anything outside this set is dropped. Claude Code keeps adding out-of-band + * SDK events (`tool_progress` heartbeats, stream events, control responses), + * and they are not conversation content — passing them through would stamp + * them with transcript base fields (parentUuid/sessionId/userType), which + * makes them indistinguishable from a real log line downstream. The web + * normalizer can't match them to any known shape and falls back to rendering + * the raw envelope as message text, leaking JSON into the chat. + * + * The local launcher already enforces the same allowlist via + * `RawJSONLinesSchema.safeParse` in sessionScanner; this keeps the remote + * (SDK) path at parity instead of leaving it open by default. + */ +const CONVERTIBLE_SDK_MESSAGE_TYPES = new Set([ + 'user', + 'assistant', + 'system', + 'result', + 'tool_result' +]) /** * Context for converting SDK messages to log format @@ -200,6 +224,13 @@ export class SDKToLogConverter { return this.convertRateLimitEvent(sdkMessage) } + // Bail before allocating a uuid or touching sidechain/parent tracking — + // an unknown event must not advance the transcript chain it never joins. + if (!CONVERTIBLE_SDK_MESSAGE_TYPES.has(sdkMessage.type)) { + logger.debug(`[sdkToLogConverter] dropping unsupported SDK message type: ${sdkMessage.type}`) + return null + } + const uuid = randomUUID() const timestamp = new Date().toISOString() let parentUuid = this.lastUuid; @@ -398,12 +429,12 @@ export class SDKToLogConverter { } default: - // Unknown message type - pass through with all fields - logMessage = { - ...baseFields, - ...sdkMessage, - type: (sdkMessage as any).type // Override type last to ensure it's set - } as any + // Unreachable: CONVERTIBLE_SDK_MESSAGE_TYPES gates this switch. + // Kept as a fail-closed guard so that adding a type to the set + // without a matching case here drops the message instead of + // passing an unshaped envelope through to the chat. + logger.debug(`[sdkToLogConverter] no case for allowlisted type: ${(sdkMessage as any).type}`) + break } // Update last UUID for parent tracking