diff --git a/src/main/claude/claude-adapter-capture-replay.test.ts b/src/main/claude/claude-adapter-capture-replay.test.ts index 8e877a135a83..8e2c953c4965 100644 --- a/src/main/claude/claude-adapter-capture-replay.test.ts +++ b/src/main/claude/claude-adapter-capture-replay.test.ts @@ -26,6 +26,9 @@ import { identityFor, PROVIDER_SESSION_ID } from './claude-structured-session-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger type CapturedEvent = | { at: number; kind: 'meta'; providerSessionId: string } @@ -108,6 +111,7 @@ async function replayCapture(name: string): Promise { // The capture supplies every frame, startup proof included. const claude = fakeClaude({ initProof: 'none', replayUuid: null }) const deps: ClaudeStructuredSessionAdapterDeps = { + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-agent-sdk-contract-pins.test.ts b/src/main/claude/claude-agent-sdk-contract-pins.test.ts index dcd331d70a4f..64c821353e83 100644 --- a/src/main/claude/claude-agent-sdk-contract-pins.test.ts +++ b/src/main/claude/claude-agent-sdk-contract-pins.test.ts @@ -18,6 +18,9 @@ import { LOCAL_EXECUTION_HOST_ID } from '../../shared/execution-host' import type { AgentSessionRecordStore } from '../runtime/agent-session-record-store' import { claudeQuerySettingsReader } from './claude-agent-sdk-control-requests' import { createClaudeStructuredLaunchResolver } from './claude-structured-launch-resolution' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger // Contract pins for @anthropic-ai/claude-agent-sdk, run against the real SDK // driving a scripted fake CLI (never the real Claude binary). These tests exist @@ -159,6 +162,7 @@ function resolvedLaunch(permissionMode: PermissionMode, launchArgs: string[] = [ launchArgs } as unknown as AgentSessionRecord return createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async () => '/repos/workspace-1', resolveCommand: () => FAKE_CLI, diff --git a/src/main/claude/claude-at-rest-commands.ts b/src/main/claude/claude-at-rest-commands.ts index 7eaa9c143ed3..e4ba94dedca5 100644 --- a/src/main/claude/claude-at-rest-commands.ts +++ b/src/main/claude/claude-at-rest-commands.ts @@ -5,6 +5,7 @@ import { structuredSlashCommands } from '../../shared/structured-agent-session-c import { discoverSkills } from '../skills/discovery' import { scanClaudeCommandFolders } from './claude-command-folder-scan' import { supportsClaudeStructuredLocation } from './claude-structured-location-support' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' /** How long one scan answers for a workspace and account before the next read scans again. */ export const CLAUDE_AT_REST_COMMANDS_TTL_MS = 10_000 @@ -14,6 +15,7 @@ const SCAN_OVERDUE_MS = 30_000 const MAX_SCANS_IN_FLIGHT = 2 export type ClaudeAtRestCommandsDeps = { + logger: StructuredAgentSessionLogger resolveWorkspacePath: (workspaceId: string) => Promise now?: () => number discover?: typeof discoverSkills @@ -101,7 +103,11 @@ export class ClaudeAtRestCommandCatalog { (error: unknown) => { // Waits out the window before trying again, but leaves room for an older scan's answer. entry.scannedAt = this.now() - console.warn('[claude] reading the at-rest `/` commands failed:', error) + this.deps.logger.warn('reading the at-rest `/` commands failed', { + scope: 'claude-at-rest-commands', + sessionId: record.sessionId, + error + }) } ) .finally(() => { diff --git a/src/main/claude/claude-child-work-producer-harness.test-fixture.ts b/src/main/claude/claude-child-work-producer-harness.test-fixture.ts index 0b460d91b4a7..056da5c74280 100644 --- a/src/main/claude/claude-child-work-producer-harness.test-fixture.ts +++ b/src/main/claude/claude-child-work-producer-harness.test-fixture.ts @@ -22,6 +22,9 @@ import { identityFor, PROVIDER_SESSION_ID } from './claude-structured-session-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger export const parent = makeStructuredAgentStatusSubject( { @@ -115,6 +118,7 @@ export async function producer(host?: AgentHookServer) { const evidenceLog: AgentChildWorkEvidence[][] = [] const ingested: (AgentChildWorkReconcileOutcome | null)[] = [] const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-command-lifecycle.test.ts b/src/main/claude/claude-command-lifecycle.test.ts index f4182a601747..c1eabaae77d5 100644 --- a/src/main/claude/claude-command-lifecycle.test.ts +++ b/src/main/claude/claude-command-lifecycle.test.ts @@ -25,6 +25,9 @@ import { PROVIDER_SESSION_ID, type FakeConnection } from './claude-structured-session-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger type CapturedEvent = | { kind: 'meta'; providerSessionId: string } @@ -115,6 +118,7 @@ async function replayCapture( // The capture supplies every frame, startup proof included. const claude = fakeClaude({ initProof: 'none', replayUuid: null }) const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-fold-steer-receipt.test.ts b/src/main/claude/claude-fold-steer-receipt.test.ts index 4726dc55d823..7506326f6c40 100644 --- a/src/main/claude/claude-fold-steer-receipt.test.ts +++ b/src/main/claude/claude-fold-steer-receipt.test.ts @@ -50,6 +50,9 @@ import { twoSteersCapture, TWO_STEERS_SEND_AT } from './claude-captured-fold-steer-frames.test-fixture' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const T0 = 1_700_000_100_000 @@ -80,6 +83,7 @@ async function riggedAdapter( const settled = vi.fn() const claude = fakeClaude({ replayUuid: null, ...claudeOptions }) const deps: ClaudeStructuredSessionAdapterDeps = { + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-history-window-source-budget.test.ts b/src/main/claude/claude-history-window-source-budget.test.ts index 90d74b94e373..19c117b5d138 100644 --- a/src/main/claude/claude-history-window-source-budget.test.ts +++ b/src/main/claude/claude-history-window-source-budget.test.ts @@ -10,6 +10,9 @@ import { tmpdir } from 'node:os' import type { FileHandle } from 'node:fs/promises' import type * as FsPromises from 'node:fs/promises' import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const state = vi.hoisted(() => ({ path: '', @@ -95,6 +98,7 @@ let directory = '' const read = (previousLeafUuid: string | null = 'anchor') => readClaudeProviderHistoryWindow({ + logger: TEST_LOGGER, transcriptPath: state.path, providerSessionId: 'provider', previousLeafUuid, diff --git a/src/main/claude/claude-stop-ack-race.test.ts b/src/main/claude/claude-stop-ack-race.test.ts index 5f2f60d3a692..c0b8fdc7dd14 100644 --- a/src/main/claude/claude-stop-ack-race.test.ts +++ b/src/main/claude/claude-stop-ack-race.test.ts @@ -21,6 +21,7 @@ import { import { stopClaudeBackgroundTasks } from './claude-structured-control-actions' import { CLAUDE_STRUCTURED_BASE_OPTIONS } from './claude-structured-launch-resolution' import type { ClaudeSession } from './claude-structured-session-state' +import { testEventSinkLogging } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' const FAKE_CLI = join(__dirname, '__fixtures__', 'claude-agent-sdk-scripted-cli.mjs') const SESSION_ID = '5348c19f-6a54-4c2e-9c68-9c2b1a3d4e5f' @@ -107,6 +108,7 @@ async function stoppedAsItCompleted(ahead: number) { } }, { + ...testEventSinkLogging(), onMessage: (message) => { seen.push(`${String(message.type)}:${String(message.subtype ?? '')}`) decoder.observe(message) diff --git a/src/main/claude/claude-stream-json-connection-close.test.ts b/src/main/claude/claude-stream-json-connection-close.test.ts index 22076f3600ea..36956450adf2 100644 --- a/src/main/claude/claude-stream-json-connection-close.test.ts +++ b/src/main/claude/claude-stream-json-connection-close.test.ts @@ -7,6 +7,10 @@ import { openClaudeStreamJsonConnection, type ClaudeStreamJsonLaunch } from './claude-stream-json-connection' +import { + recordingStructuredAgentSessionLogger, + testEventSinkLogging +} from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' const mocks = vi.hoisted(() => { const refresh = vi.fn() @@ -66,6 +70,7 @@ describe('Claude stream-json close ordering', () => { connection = await openClaudeStreamJsonConnection( { pathToClaudeCodeExecutable: 'claude', options: {}, cwd: '/work/repo' }, { + ...testEventSinkLogging(), onMessage: (message) => { seen.push(String(message.type)) if (message.type === 'first') { @@ -115,6 +120,7 @@ describe('Claude stream-json close ordering', () => { const connection = await openClaudeStreamJsonConnection( { pathToClaudeCodeExecutable: 'claude', options: {}, cwd: '/work/repo' }, { + ...testEventSinkLogging(), onMessage: (message) => events.push(`message:${String(message.type)}`), onExit: () => events.push('exit') }, @@ -153,7 +159,7 @@ describe('Claude stream-json close ordering', () => { }) as unknown as typeof query const connection = await openClaudeStreamJsonConnection( { pathToClaudeCodeExecutable: 'claude', options: {}, cwd: '/work/repo' }, - {}, + testEventSinkLogging(), () => child, queryImpl ) @@ -190,7 +196,12 @@ describe('Claude stream-json close ordering', () => { })() return (async function* () {})() }) as typeof query - const connection = await openClaudeStreamJsonConnection(launch, {}, () => child, queryImpl) + const connection = await openClaudeStreamJsonConnection( + launch, + testEventSinkLogging(), + () => child, + queryImpl + ) const closing = connection.close() await new Promise((resolve) => setImmediate(resolve)) @@ -231,7 +242,12 @@ describe('Claude stream-json close ordering', () => { })() return (async function* () {})() }) as typeof query - const connection = await openClaudeStreamJsonConnection(launch, {}, () => child, queryImpl) + const connection = await openClaudeStreamJsonConnection( + launch, + testEventSinkLogging(), + () => child, + queryImpl + ) child.stderr.emit('data', 'output') await vi.waitFor(() => expect(mocks.refresh).toHaveBeenCalledTimes(1)) @@ -248,4 +264,40 @@ describe('Claude stream-json close ordering', () => { await expect(closing).resolves.toBe(true) expect(child.stdin.writableEnded).toBe(true) }) + + it('reports a descendant that outlived an exited root through the chat logger', async () => { + mocks.refresh.mockReset() + mocks.proveClaudeChildExit.mockReset() + mocks.refresh.mockResolvedValue(undefined) + mocks.proveClaudeChildExit.mockResolvedValueOnce(false) + const child = fakeChild() + // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: This injected query only has to spawn the child; the close never reads a message. + const queryImpl = ((params: Parameters[0]) => { + params.options?.spawnClaudeCodeProcess?.({ + command: 'claude', + args: [], + env: {}, + signal: new AbortController().signal + }) + return (async function* () {})() + }) as typeof query + const logged = recordingStructuredAgentSessionLogger() + const connection = await openClaudeStreamJsonConnection( + { pathToClaudeCodeExecutable: 'claude', options: {}, cwd: '/work/repo' }, + { sessionId: 'session-1', logger: logged.logger }, + () => child, + queryImpl + ) + child.emit('exit', 0, null) + Object.assign(mocks.tree, { treeVerdict: 'live' }) + try { + await expect(connection.close()).resolves.toBe(false) + } finally { + Object.assign(mocks.tree, { treeVerdict: 'unverifiable' }) + } + + expect(logged.entries.map((entry) => entry.fields)).toEqual([ + { scope: 'claude-close-descendant', sessionId: 'session-1', pid: 424242 } + ]) + }) }) diff --git a/src/main/claude/claude-stream-json-connection.test.ts b/src/main/claude/claude-stream-json-connection.test.ts index 082ed4c12ce7..d565ae9710ce 100644 --- a/src/main/claude/claude-stream-json-connection.test.ts +++ b/src/main/claude/claude-stream-json-connection.test.ts @@ -91,12 +91,12 @@ const spawnedChildren: SpawnedProcess[] = [] async function open( launch: ClaudeStreamJsonLaunch, - handlers: Parameters[1] = {}, + handlers: Omit[1], 'sessionId' | 'logger'> = {}, queryImpl?: typeof query ): Promise { const connection = await openClaudeStreamJsonConnection( launch, - handlers, + { ...testEventSinkLogging(), ...handlers }, (spec) => { spawned.push(spec) const child = spawnProcess(spec) @@ -804,7 +804,7 @@ describe('the managed-auth live gate', () => { try { await expect( - openClaudeStreamJsonConnection(launchFor(scenario), {}, (spec) => { + openClaudeStreamJsonConnection(launchFor(scenario), testEventSinkLogging(), (spec) => { const child = spawnProcess(spec) started = child const attach = child.stderr.on.bind(child.stderr) diff --git a/src/main/claude/claude-stream-json-connection.ts b/src/main/claude/claude-stream-json-connection.ts index 6f67e04b36ea..4e6ea653c65e 100644 --- a/src/main/claude/claude-stream-json-connection.ts +++ b/src/main/claude/claude-stream-json-connection.ts @@ -22,6 +22,7 @@ import { createClaudeUserMessageQueue } from './claude-agent-sdk-user-message-queue' import type { ClaudeStructuredSdkOptions } from './claude-structured-launch-resolution' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' export { ClaudeControlRequestError } @@ -53,6 +54,9 @@ export type ClaudeStreamJsonLaunch = { } export type ClaudeStreamJsonConnectionHandlers = { + /** The chat this connection serves, and where its close reports what it could not reap. */ + sessionId: string + logger: StructuredAgentSessionLogger onMessage?: (message: Record) => void /** * The SDK owns inbound permission control: it hands `can_use_tool` to this callback with @@ -114,7 +118,7 @@ function exitError(stderrTail: string, status: ExitStatus | null, cause?: Error) export async function openClaudeStreamJsonConnection( launch: ClaudeStreamJsonLaunch, - handlers: ClaudeStreamJsonConnectionHandlers = {}, + handlers: ClaudeStreamJsonConnectionHandlers, spawnImpl: typeof spawnProcess = spawnProcess, queryImpl?: typeof ClaudeAgentSdk.query ): Promise { @@ -323,7 +327,9 @@ export async function openClaudeStreamJsonConnection( inbox.fail(new Error('claude stream-json connection closed')) if (!proven) { if (exited && tree.treeVerdict === 'live') { - console.warn('[claude-stream-json] root exited but a descendant survived the close:', { + handlers.logger.warn('the Claude process exited but a descendant survived the close', { + scope: 'claude-close-descendant', + sessionId: handlers.sessionId, pid: spawner.pid }) } diff --git a/src/main/claude/claude-structured-auth-parity.test.ts b/src/main/claude/claude-structured-auth-parity.test.ts index 002240e4dd77..aa99b1a04255 100644 --- a/src/main/claude/claude-structured-auth-parity.test.ts +++ b/src/main/claude/claude-structured-auth-parity.test.ts @@ -15,6 +15,9 @@ import { fakeClaude, identityFor } from './claude-structured-session-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION_ID = 'orca-session-auth' const IDENTITY = { sessionId: SESSION_ID } as Parameters< @@ -42,6 +45,7 @@ function resolverFor(options: { authSwitchSettleTimeoutMs?: number }): ReturnType { return createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record() } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', @@ -67,7 +71,9 @@ function realResolverAdapter( ] } as unknown as AgentSessionRecord return new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => resumable } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', diff --git a/src/main/claude/claude-structured-dispatch-attachment-rejection.test.ts b/src/main/claude/claude-structured-dispatch-attachment-rejection.test.ts index a23767c09681..13a99db98a1f 100644 --- a/src/main/claude/claude-structured-dispatch-attachment-rejection.test.ts +++ b/src/main/claude/claude-structured-dispatch-attachment-rejection.test.ts @@ -152,8 +152,8 @@ describe('Claude structured dispatch attachment rejections', () => { }) it('rejects an attachment it cannot read with the generic sentence and no path', async () => { - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) const session = sessionFor() + const warn = vi.spyOn(session.logger, 'warn') const path = join(tmpdir(), 'orca-claude-image-missing', 'gone.png') await expect( @@ -169,9 +169,12 @@ describe('Claude structured dispatch attachment rejections', () => { expect(session.connection.send).not.toHaveBeenCalled() // The row drops the error, so the log is the only place left to find why. expect(warn).toHaveBeenCalledWith( - '[claude-dispatch] attachment could not be read:', - expect.objectContaining({ code: 'ENOENT' }) + 'an attachment could not be read', + expect.objectContaining({ + scope: 'claude-attachment-read', + sessionId: session.sessionId, + error: expect.objectContaining({ code: 'ENOENT' }) + }) ) - warn.mockRestore() }) }) diff --git a/src/main/claude/claude-structured-dispatch-content.ts b/src/main/claude/claude-structured-dispatch-content.ts index 035b0a594926..e8a915ae7c3a 100644 --- a/src/main/claude/claude-structured-dispatch-content.ts +++ b/src/main/claude/claude-structured-dispatch-content.ts @@ -14,6 +14,7 @@ import { } from '../../shared/agent-session-failure-words' import { TUI_AGENT_DISPLAY_NAMES } from '../../shared/tui-agent-display-names' import { claudeRecord } from './claude-structured-item-translation' +import type { ClaudeSession } from './claude-structured-session-state' /** Orca refused the message's content, as opposed to failing to read an attachment. */ export class ClaudeDispatchContentError extends Error { @@ -47,12 +48,19 @@ export function claudeDispatchRejection( /** Why a message whose content could not be built was not sent: Orca's own refusal of it, or an * attachment it could not read. Never the provider. */ -export function claudeDispatchContentRejection(error: unknown): AgentJournalDispatchRejection { +export function claudeDispatchContentRejection( + error: unknown, + session: Pick +): AgentJournalDispatchRejection { if (error instanceof ClaudeDispatchContentError) { return claudeDispatchRejection(error.failure) } // The row says only that it could not be read; why belongs in the log. - console.warn('[claude-dispatch] attachment could not be read:', error) + session.logger.warn('an attachment could not be read', { + scope: 'claude-attachment-read', + sessionId: session.sessionId, + error + }) return claudeDispatchRejection(agentSessionFailureFact('attachmentUnreadable')) } diff --git a/src/main/claude/claude-structured-dispatch-test-support.ts b/src/main/claude/claude-structured-dispatch-test-support.ts index 5af0f17243b5..3111cf08fa73 100644 --- a/src/main/claude/claude-structured-dispatch-test-support.ts +++ b/src/main/claude/claude-structured-dispatch-test-support.ts @@ -6,10 +6,13 @@ import { ClaudeBackgroundTaskTracker } from './claude-background-task-tracker' import { ClaudeChildWorkDecoder } from './claude-child-work-decoder' import { ClaudeSlashCommandCatalog } from './claude-slash-command-catalog' import { createClaudeSessionStartup } from './claude-structured-session-startup-state' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' export function sessionFor(send: Mock = vi.fn().mockResolvedValue(undefined)): ClaudeSession { return { connection: { send } as unknown as ClaudeSession['connection'], + sessionId: 'session-1', + logger: recordingStructuredAgentSessionLogger().logger, providerSessionId: 'provider-session', leafUuid: null, turnEndLeafUuid: null, diff --git a/src/main/claude/claude-structured-dispatch.test.ts b/src/main/claude/claude-structured-dispatch.test.ts index 92ae0253711a..96d501bf7875 100644 --- a/src/main/claude/claude-structured-dispatch.test.ts +++ b/src/main/claude/claude-structured-dispatch.test.ts @@ -397,12 +397,12 @@ describe('Claude structured dispatch image limits', () => { }) it('does not let a provably unwritten attempt block retry correlation', async () => { - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) const send = vi .fn() .mockRejectedValueOnce(claudeUnwrittenUserMessageError(new Error('broken pipe'))) .mockResolvedValue(undefined) const session = sessionFor(send) + const warn = vi.spyOn(session.logger, 'warn') const body = userMessage([{ type: 'text', text: 'retry me' }]) await expect( @@ -414,10 +414,13 @@ describe('Claude structured dispatch image limits', () => { }) // The row keeps only the marker; why the write failed goes to the log. expect(warn).toHaveBeenCalledWith( - '[claude-dispatch] message could not be handed to Claude:', - expect.objectContaining({ message: expect.stringContaining('broken pipe') }) + 'a message could not be handed to Claude', + expect.objectContaining({ + scope: 'claude-dispatch-write', + sessionId: session.sessionId, + error: expect.objectContaining({ message: expect.stringContaining('broken pipe') }) + }) ) - warn.mockRestore() expect(session.dispatchWaiters).toHaveLength(0) expect(session.retiredDispatchWaiters).toHaveLength(0) diff --git a/src/main/claude/claude-structured-dispatch.ts b/src/main/claude/claude-structured-dispatch.ts index 87e706ddbbc3..436468c0c03c 100644 --- a/src/main/claude/claude-structured-dispatch.ts +++ b/src/main/claude/claude-structured-dispatch.ts @@ -107,8 +107,15 @@ export function retireClaudeDispatchWaiters(session: ClaudeSession): void { } /** The row keeps only the marker released clients hide; why the write failed belongs in the log. */ -function claudeWriteFailureRejection(error: unknown): AgentJournalDispatchRejection { - console.warn('[claude-dispatch] message could not be handed to Claude:', error) +function claudeWriteFailureRejection( + error: unknown, + session: ClaudeSession +): AgentJournalDispatchRejection { + session.logger.warn('a message could not be handed to Claude', { + scope: 'claude-dispatch-write', + sessionId: session.sessionId, + error + }) return claudeDispatchRejection(agentSessionFailureFact('writeFailed')) } @@ -127,7 +134,7 @@ export async function dispatchClaudeTurn( try { content = await claudeDispatchMessageContent(input.body) } catch (error) { - return { state: 'rejected', ...claudeDispatchContentRejection(error) } + return { state: 'rejected', ...claudeDispatchContentRejection(error, session) } } if (session.dispatchWaiters.length >= MAX_ACTIVE_DISPATCH_WAITERS) { return { state: 'rejected', ...claudeDispatchRejection(agentSessionFailureFact('queueFull')) } @@ -180,7 +187,7 @@ export async function dispatchClaudeTurn( if (error instanceof AgentSessionPreDispatchError) { throw error } - return { state: 'rejected', ...claudeWriteFailureRejection(error) } + return { state: 'rejected', ...claudeWriteFailureRejection(error, session) } } const waiter = replay.waiter if (waiter.settledUuid) { @@ -198,7 +205,7 @@ export async function dispatchClaudeTurn( waiter.resolve(null) // The frame was never handed to the SDK's input pump, so this is not doubt: // the message provably did not happen, which is what `rejected` means. - return { state: 'rejected', ...claudeWriteFailureRejection(error) } + return { state: 'rejected', ...claudeWriteFailureRejection(error, session) } } if (!waiter.retired) { retireWaiter(session, waiter) diff --git a/src/main/claude/claude-structured-effort-default-at-rest.test.ts b/src/main/claude/claude-structured-effort-default-at-rest.test.ts index 0228b1171683..df37db26e090 100644 --- a/src/main/claude/claude-structured-effort-default-at-rest.test.ts +++ b/src/main/claude/claude-structured-effort-default-at-rest.test.ts @@ -26,6 +26,9 @@ import { identityFor, recordingJournalSink } from './claude-structured-session-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION = 'session-1' const ACCOUNT_HOME = '/accounts/claude' @@ -95,6 +98,7 @@ async function startChild( cli: { runs?: string; lists?: unknown[] } = {} ): Promise { const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-structured-history-window.test.ts b/src/main/claude/claude-structured-history-window.test.ts index 851831b86f19..86c9a0169d54 100644 --- a/src/main/claude/claude-structured-history-window.test.ts +++ b/src/main/claude/claude-structured-history-window.test.ts @@ -13,6 +13,9 @@ import { claudeProviderHistoryWindowFromJsonl, resolveClaudeProviderHistoryWindow } from './claude-structured-history-window' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const PROVIDER_SESSION = 'provider-1' const ORCA_SESSION = 'session-1' @@ -77,6 +80,7 @@ describe('claudeProviderHistoryWindowFromJsonl', () => { ) const window = await resolveClaudeProviderHistoryWindow({ + logger: TEST_LOGGER, identity: { sessionId: ORCA_SESSION, workspaceId: 'workspace-1', diff --git a/src/main/claude/claude-structured-history-window.ts b/src/main/claude/claude-structured-history-window.ts index 00ae86920251..8904c9104ef4 100644 --- a/src/main/claude/claude-structured-history-window.ts +++ b/src/main/claude/claude-structured-history-window.ts @@ -25,6 +25,7 @@ import { claudeContentBlocks } from '../native-chat/transcript-record-blocks' import { isKnownHarnessInjectedUserTurnText } from '../../shared/harness-injected-user-turns' import { computeAgentSessionPayloadFingerprint } from '../../shared/agent-session-mutation-envelope' import type { NativeChatBlock } from '../../shared/native-chat-types' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' import { replayClaudeTranscriptBranchAncestry, replayClaudeTranscriptBranchAncestryFromJsonl @@ -240,6 +241,7 @@ export async function resolveClaudeProviderHistoryWindow(input: { identity: AgentSessionJournalIdentity accountHomePath: string hasLiveSession: boolean + logger: StructuredAgentSessionLogger }): Promise { const handle = input.identity.providerHandle if (handle.kind !== 'claude') { @@ -256,12 +258,13 @@ export async function resolveClaudeProviderHistoryWindow(input: { providerSessionId: handle.sessionId, previousLeafUuid: handle.leafUuid, sessionId: input.identity.sessionId, - turnInFlight: input.hasLiveSession + turnInFlight: input.hasLiveSession, + logger: input.logger }) } export async function readClaudeProviderHistoryWindow( - input: HistoryWindowInput & { transcriptPath: string } + input: HistoryWindowInput & { transcriptPath: string; logger: StructuredAgentSessionLogger } ): Promise { const ancestryAnchorUuid = input.previousLeafUuid if (!ancestryAnchorUuid) { @@ -282,9 +285,10 @@ export async function readClaudeProviderHistoryWindow( // Unreadable, unprovable, or a single record too large to frame: all of them // leave the boundary unvouched for, which is not the same as an empty window. // Oversize is no longer among them, so only the log separates what is left. - console.warn('[claude-history-window] transcript unprovable; boundary inconsistent:', { - transcriptPath: input.transcriptPath, + input.logger.warn('the transcript is unprovable, so the history boundary is inconsistent', { + scope: 'claude-history-window', sessionId: input.sessionId, + transcriptPath: input.transcriptPath, error }) return INCONSISTENT diff --git a/src/main/claude/claude-structured-launch-resolution.test.ts b/src/main/claude/claude-structured-launch-resolution.test.ts index 66fed64c3230..97f8d4d9526d 100644 --- a/src/main/claude/claude-structured-launch-resolution.test.ts +++ b/src/main/claude/claude-structured-launch-resolution.test.ts @@ -16,6 +16,9 @@ import { createClaudeStructuredLaunchResolver } from './claude-structured-launch-resolution' import { claudeStructuredPermissionModeForSettings } from './claude-structured-permission-mode' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION_ID = 'orca-session-1' const IDENTITY = { sessionId: SESSION_ID } as Parameters< @@ -62,6 +65,7 @@ function resolverFor( hasTranscript: () => Promise = async () => true ) { return createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => value } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', @@ -356,6 +360,7 @@ describe('claude structured launch resolution', () => { it('builds on the supplied inherited env instead of Orca process env', async () => { const launch = await createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record() } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', @@ -368,6 +373,7 @@ describe('claude structured launch resolution', () => { it('drops an inherited CLAUDE_CONFIG_DIR so the record stays the only Claude home the pin sees', async () => { const launch = await createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record() } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', @@ -386,6 +392,7 @@ describe('claude structured launch resolution', () => { it('keeps a configured overlay CLAUDE_CONFIG_DIR over the dropped inherited one', async () => { const launch = await createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record() } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', @@ -399,6 +406,7 @@ describe('claude structured launch resolution', () => { it('still strips an inherited auth key under a managed account', async () => { const launch = await createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record() } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', @@ -436,6 +444,7 @@ describe('claude structured launch resolution', () => { makeExecutable(nodeCommand) const launch = await createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => record() } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => claudeCommand, @@ -478,6 +487,7 @@ describe('claude structured launch resolution', () => { describe('managed-account gate on every acquisition', () => { function resolverWithGate(read: () => ClaudeManagedAccountGateSettings | null) { return createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, store: { getRecord: () => RESUMABLE } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveCommand: () => '/usr/local/bin/claude', diff --git a/src/main/claude/claude-structured-launch-resolution.ts b/src/main/claude/claude-structured-launch-resolution.ts index 29703dfd8eb7..b1adb78176ae 100644 --- a/src/main/claude/claude-structured-launch-resolution.ts +++ b/src/main/claude/claude-structured-launch-resolution.ts @@ -30,6 +30,7 @@ import { resolveClaudeCommand } from '../codex-cli/command' import { resolveSessionFilePath } from '../native-chat/session-file-resolver' import { withoutInheritedClaudeConfigDir } from './claude-config-dir-pin' import type { AgentSessionRecordStore } from '../runtime/agent-session-record-store' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' export const CLAUDE_DEFAULT_SETTING_SOURCES = ['user', 'project', 'local'] as const export const CLAUDE_SESSION_STATE_EVENTS_ENV = 'CLAUDE_CODE_EMIT_SESSION_STATE_EVENTS' @@ -107,6 +108,8 @@ export type ClaudeStructuredLaunch = { export type ClaudeStructuredLaunchResolverDeps = { store: AgentSessionRecordStore + /** Where a launch step that carries on past a failure reports it: the host's logger. */ + logger: StructuredAgentSessionLogger resolveWorkspacePath: (workspaceId: string) => Promise resolveCommand?: () => string resolveEnv?: () => @@ -289,11 +292,15 @@ export function createClaudeStructuredLaunchResolver( ) const { command, env } = await resolveClaudeStructuredInvocation(deps, (base) => // Every structured session speaks orchestration as itself: its injected id and the Orca CLI. - structuredSessionChildIdentityEnv(record.sessionId, { - ...base, - // The turn translator relies on Claude's authoritative idle frame when no result arrives. - [CLAUDE_SESSION_STATE_EVENTS_ENV]: '1' - }) + structuredSessionChildIdentityEnv( + record.sessionId, + { + ...base, + // The turn translator relies on Claude's authoritative idle frame when no result arrives. + [CLAUDE_SESSION_STATE_EVENTS_ENV]: '1' + }, + deps.logger + ) ) return { pathToClaudeCodeExecutable: command, diff --git a/src/main/claude/claude-structured-options.test.ts b/src/main/claude/claude-structured-options.test.ts index e5b7a7ea8a77..c8912288f5d4 100644 --- a/src/main/claude/claude-structured-options.test.ts +++ b/src/main/claude/claude-structured-options.test.ts @@ -17,6 +17,9 @@ import { observeClaudeFastModeFacts, readClaudeStructuredSessionOptions } from './claude-structured-session-options' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger function sessionFor(setModel: ClaudeSession['connection']['setModel']): ClaudeSession { return { @@ -26,6 +29,8 @@ function sessionFor(setModel: ClaudeSession['connection']['setModel']): ClaudeSe setModel, supportedModels: async (): Promise => [] } as ClaudeSession['connection'], + sessionId: 'session-1', + logger: TEST_LOGGER, providerSessionId: 'provider-session', leafUuid: null, turnEndLeafUuid: null, @@ -458,10 +463,25 @@ describe('Claude structured option restore under the request deadline', () => { ['effort', 'high'], ['permissionMode', 'plan'] ]) - vi.spyOn(console, 'warn').mockImplementation(() => {}) + const logged = recordingStructuredAgentSessionLogger() + session.logger = logged.logger await expect(restoreClaudeStructuredSessionOptions(session, 10)).resolves.toBeUndefined() + expect(logged.entries.map(({ level, fields }) => ({ level, ...fields }))).toEqual([ + expect.objectContaining({ + level: 'warn', + scope: 'claude-option-restore', + sessionId: 'session-1', + key: 'model' + }), + expect.objectContaining({ + level: 'warn', + scope: 'claude-option-restore', + sessionId: 'session-1', + key: 'effort' + }) + ]) expect(Object.fromEntries(session.options)).toEqual({ model: 'sonnet', effort: 'high' }) expect([...session.restoreSkippedOptions]).toEqual(['permissionMode']) expect(claudeStructuredSessionOptionsFrom(session, null).current).toEqual({ diff --git a/src/main/claude/claude-structured-options.ts b/src/main/claude/claude-structured-options.ts index 2f0b7ac4b707..eec779a359cf 100644 --- a/src/main/claude/claude-structured-options.ts +++ b/src/main/claude/claude-structured-options.ts @@ -268,9 +268,12 @@ export async function restoreClaudeStructuredSessionOptions( // A write the CLI never answered must not fault a start that is otherwise fine. Silence is // not a refusal, so the choice stays wanted, unconfirmed, and the next start retries it. if (error instanceof ClaudeControlRequestTimeoutError) { - console.warn( - `[claude-structured] restore of ${key} for ${session.providerSessionId} was not answered in time; keeping it unconfirmed` - ) + session.logger.warn('restoring an option was not answered in time; it stays unconfirmed', { + scope: 'claude-option-restore', + sessionId: session.sessionId, + providerSessionId: session.providerSessionId, + key + }) session.options.set(key, value) session.confirmedOptions.delete(key) continue diff --git a/src/main/claude/claude-structured-real-cli-fold.test.ts b/src/main/claude/claude-structured-real-cli-fold.test.ts index 5ce21d83f170..599a221dad89 100644 --- a/src/main/claude/claude-structured-real-cli-fold.test.ts +++ b/src/main/claude/claude-structured-real-cli-fold.test.ts @@ -27,6 +27,9 @@ import { realClaudeCommand, realClaudeLaunchHome } from './claude-real-cli-availability-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION_ID = 'real-cli-fold' // Pins the live proof order (SessionStart hook frame before system/init) and lets the @@ -78,6 +81,7 @@ describe.skipIf(!realClaudeAvailable)('Claude structured real CLI fold', () => { } const settled = vi.fn() const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: realClaudeCommand, options: { diff --git a/src/main/claude/claude-structured-real-cli.test.ts b/src/main/claude/claude-structured-real-cli.test.ts index 677d2de4cb9e..ada39adf729c 100644 --- a/src/main/claude/claude-structured-real-cli.test.ts +++ b/src/main/claude/claude-structured-real-cli.test.ts @@ -18,6 +18,9 @@ import { type ClaudeStructuredSessionEvent } from './claude-structured-session-adapter' import type { ClaudeStructuredSessionAdapterDeps } from './claude-structured-session-state' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const command = realClaudeCommand const suiteTitle = `Claude structured real CLI handshake${realClaudeCliGate.skipReason ? ` (skipped: ${realClaudeCliGate.skipReason})` : ''}` @@ -30,6 +33,7 @@ function realAdapter( onDispatchSettledLate?: ClaudeStructuredSessionAdapterDeps['onDispatchSettledLate'] ): ClaudeStructuredSessionAdapter { const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: command, options: { ...CLAUDE_STRUCTURED_BASE_OPTIONS, sessionId: providerSessionId }, diff --git a/src/main/claude/claude-structured-resume-point.test.ts b/src/main/claude/claude-structured-resume-point.test.ts index 862909a2cd66..76bbe0a36d88 100644 --- a/src/main/claude/claude-structured-resume-point.test.ts +++ b/src/main/claude/claude-structured-resume-point.test.ts @@ -2,6 +2,7 @@ import { afterEach, describe, expect, it, vi } from 'vitest' import type { ClaudeStructuredSessionEvent } from './claude-structured-session-adapter' import { adapterFor, + CLAUDE_ADAPTER_TEST_LOGGER, fakeClaude, identityFor, PROVIDER_SESSION_ID, @@ -106,7 +107,7 @@ describe('Claude resume point is the last completed turn on every exit path', () }) it('on an unexpected exit whose durable write fails, still ends the session and logs', async () => { - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const warn = vi.spyOn(CLAUDE_ADAPTER_TEST_LOGGER, 'warn') const events: ClaudeStructuredSessionEvent[] = [] const claude = fakeClaude() const adapter = adapterFor( @@ -135,8 +136,12 @@ describe('Claude resume point is the last completed turn on every exit path', () await tick() expect(events.at(-1)).toMatchObject({ type: 'ended', cause: 'unexpected-exit' }) expect(warn).toHaveBeenCalledWith( - '[claude-resume-point] exit cursor was not persisted:', - expect.objectContaining({ sessionId: 'session-1', error: expect.any(Error) }) + 'the exit cursor was not persisted', + expect.objectContaining({ + scope: 'claude-exit-cursor-persist', + sessionId: 'session-1', + error: expect.any(Error) + }) ) }) }) diff --git a/src/main/claude/claude-structured-resume-point.ts b/src/main/claude/claude-structured-resume-point.ts index b15d2e3507c9..67e68563eec1 100644 --- a/src/main/claude/claude-structured-resume-point.ts +++ b/src/main/claude/claude-structured-resume-point.ts @@ -12,7 +12,7 @@ import { settleClaudeTurnEndWaiters } from './claude-request-end-wait' export function persistClaudeTurnResumePoint( sessionId: string, session: ClaudeSession, - deps: Pick + deps: Pick ): void { if (session.closeFinalization || session.closeFinalized) { return @@ -38,7 +38,8 @@ export function persistClaudeTurnResumePoint( }) ) .catch((error: unknown) => { - console.warn('[claude-resume-point] turn-end resume point was not persisted:', { + deps.logger.warn('the turn-end resume point was not persisted', { + scope: 'claude-resume-point-persist', sessionId, leafUuid, error diff --git a/src/main/claude/claude-structured-session-acquisition-processless.test.ts b/src/main/claude/claude-structured-session-acquisition-processless.test.ts index eb4babdb9aca..887356b42a96 100644 --- a/src/main/claude/claude-structured-session-acquisition-processless.test.ts +++ b/src/main/claude/claude-structured-session-acquisition-processless.test.ts @@ -6,6 +6,9 @@ import type { openClaudeStreamJsonConnection } from './claude-stream-json-connection' import { ClaudeStructuredSessionAdapter } from './claude-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const PROVIDER_SESSION_ID = '819cf9f8-e43c-4ad7-b50f-54aa158a726a' const IDENTITY: AgentSessionJournalIdentity = { @@ -20,10 +23,7 @@ describe('Claude structured processless acquisition', () => { it('classifies pre-pid error and close as processless with idempotent cleanup', async () => { const fault = new Error('spawn claude ENOENT') const close = vi.fn(async () => true) - const openConnection: typeof openClaudeStreamJsonConnection = async ( - _launch, - handlers = {} - ) => { + const openConnection: typeof openClaudeStreamJsonConnection = async (_launch, handlers) => { // A failed spawn reports its error on a later tick, as child_process does. setTimeout(() => handlers.onFault?.(fault), 0) const connection: ClaudeStreamJsonConnection = { @@ -48,6 +48,7 @@ describe('Claude structured processless acquisition', () => { return connection } const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-structured-session-acquisition.ts b/src/main/claude/claude-structured-session-acquisition.ts index 404787620e95..474c88030656 100644 --- a/src/main/claude/claude-structured-session-acquisition.ts +++ b/src/main/claude/claude-structured-session-acquisition.ts @@ -27,13 +27,12 @@ import { settleClaudeSessionStartup } from './claude-structured-session-startup' import { createClaudeSessionPublication } from './claude-structured-session-publication' -import { - mintClaudeAcquisitionGeneration, - type ClaudeAcquisitionRegistry, - type ClaudeSession, - type ClaudeSessionExit, - type ClaudeStructuredSessionAdapterDeps, - type ClaudeAcquireCallbacks +import type { + ClaudeAcquisitionRegistry, + ClaudeSession, + ClaudeSessionExit, + ClaudeStructuredSessionAdapterDeps, + ClaudeAcquireCallbacks } from './claude-structured-session-state' import { resolveClaudeAcquisitionError } from './claude-structured-session-close' import { withObservedProviderExit } from '../native-chat/agent-session-wire/structured-agent-session-failure-text' @@ -193,6 +192,8 @@ export async function acquireClaudeSession({ } }, { + sessionId, + logger: deps.logger, onMessage, canUseTool, onUserDialog, @@ -240,6 +241,8 @@ export async function acquireClaudeSession({ } const publication = createClaudeSessionPublication({ connection, + sessionId, + deps, providerSessionId: launch.providerSessionId, leafUuid: observedLeafUuid, turnEndLeafUuid: launch.resumeLeafUuid, @@ -250,10 +253,7 @@ export async function acquireClaudeSession({ events: input.events, ...(unbindReadingControl ? { unbindReadingControl } : {}), process, - acquisitionGeneration: mintClaudeAcquisitionGeneration(deps), - options: restoredClaudeStructuredSessionOptions(input.options), - ...(deps.mintLinkId ? { linkId: deps.mintLinkId() } : {}), - observedAt: deps.now?.() ?? Date.now() + options: restoredClaudeStructuredSessionOptions(input.options) }) const session = publication.session liveSession = session diff --git a/src/main/claude/claude-structured-session-adapter.ts b/src/main/claude/claude-structured-session-adapter.ts index 746d603308f1..c226898a922b 100644 --- a/src/main/claude/claude-structured-session-adapter.ts +++ b/src/main/claude/claude-structured-session-adapter.ts @@ -140,7 +140,8 @@ export class ClaudeStructuredSessionAdapter implements StructuredAgentSessionAda identity: input.identity, accountHomePath: input.accountHome.path, hasLiveSession: - this.sessions.has(input.identity.sessionId) || this.exits.has(input.identity.sessionId) + this.sessions.has(input.identity.sessionId) || this.exits.has(input.identity.sessionId), + logger: this.deps.logger }) private emit(session: ClaudeSession | null, event: ClaudeStructuredSessionEvent): void { diff --git a/src/main/claude/claude-structured-session-close.test.ts b/src/main/claude/claude-structured-session-close.test.ts index 8881c6ae74b8..455cb3f24a2c 100644 --- a/src/main/claude/claude-structured-session-close.test.ts +++ b/src/main/claude/claude-structured-session-close.test.ts @@ -15,6 +15,7 @@ import { AgentSessionAcquisitionRootExitObservedError } from '../native-chat/age import { ClaudePromptRegistry } from './claude-structured-prompt-replies' import { closeClaudeSession } from './claude-structured-session-close' import { ClaudeAcquisitionRegistry } from './claude-structured-session-state' +import { testEventSinkLogging } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' describe('Claude published session close lifecycle', () => { it('reports a proven root exit when published-session close cannot prove descendants', async () => { @@ -69,11 +70,10 @@ describe('Claude published session close lifecycle', () => { }) const acquisitions = new ClaudeAcquisitionRegistry() const { attempt } = acquisitions.start('session-1', new ClaudePromptRegistry()) - attempt.connection = await claude.openConnection({ - pathToClaudeCodeExecutable: 'claude', - options: {}, - cwd: '/work/repo' - }) + attempt.connection = await claude.openConnection( + { pathToClaudeCodeExecutable: 'claude', options: {}, cwd: '/work/repo' }, + testEventSinkLogging() + ) await expect( closeClaudeSession({ sessionId: 'session-1', sessions: new Map(), acquisitions }) diff --git a/src/main/claude/claude-structured-session-exit-lifecycle.ts b/src/main/claude/claude-structured-session-exit-lifecycle.ts index 854646490a8c..6f678d0c36f8 100644 --- a/src/main/claude/claude-structured-session-exit-lifecycle.ts +++ b/src/main/claude/claude-structured-session-exit-lifecycle.ts @@ -22,7 +22,7 @@ export type ClaudeExitLifecycle = { exits: Map /** A settled exit's diagnostic, kept for a send admitted before the host heard of the exit. */ settledExitErrors: Map - deps: Pick + deps: Pick emit: (session: ClaudeSession, event: ClaudeStructuredSessionEvent) => void } @@ -80,7 +80,11 @@ export function settleClaudeUnexpectedExit( // event that lets the host release and reacquire this exact child. await persistClaudeSessionHandle(sessionId, exit.session, deps).catch((error: unknown) => { // Recovery still publishes: the record keeps its last durable point, and the loss is logged. - console.warn('[claude-resume-point] exit cursor was not persisted:', { sessionId, error }) + deps.logger.warn('the exit cursor was not persisted', { + scope: 'claude-exit-cursor-persist', + sessionId, + error + }) }) if (exits.get(sessionId) !== exit) { settleClaudeExitedSession(exit.session) diff --git a/src/main/claude/claude-structured-session-publication.ts b/src/main/claude/claude-structured-session-publication.ts index c685c2cd2ae7..00fc74ea004a 100644 --- a/src/main/claude/claude-structured-session-publication.ts +++ b/src/main/claude/claude-structured-session-publication.ts @@ -2,7 +2,11 @@ import type { AgentSessionAcquisition } from '../native-chat/agent-session-wire/ import { claudeProviderHandleLink } from './claude-structured-owner-identity' import type { ClaudePromptRegistry } from './claude-structured-prompt-replies' import type { ClaudeJournalTranslator } from './claude-journal-translator-contract' -import type { ClaudeSession } from './claude-structured-session-state' +import { + mintClaudeAcquisitionGeneration, + type ClaudeSession, + type ClaudeStructuredSessionAdapterDeps +} from './claude-structured-session-state' import { ClaudeBackgroundTaskTracker } from './claude-background-task-tracker' import { ClaudeChildWorkDecoder } from './claude-child-work-decoder' import { ClaudeSlashCommandCatalog } from './claude-slash-command-catalog' @@ -11,12 +15,16 @@ import { createClaudeSessionStartup } from './claude-structured-session-startup- /** The session as published at spawn: nothing the CLI reports at init is assumed yet. */ export function createClaudeSessionPublication(input: { connection: ClaudeSession['connection'] + sessionId: string + deps: Pick< + ClaudeStructuredSessionAdapterDeps, + 'logger' | 'mintAcquisitionGeneration' | 'mintLinkId' | 'now' + > providerSessionId: string leafUuid: string | null /** The launch's stored leaf: a frame seen before publication is not a completed turn. */ turnEndLeafUuid: string | null fence: number - acquisitionGeneration: string /** The record's chain already heads this provider session: the link resumes, never creates. */ continuesChain: boolean prompts: ClaudePromptRegistry @@ -24,10 +32,11 @@ export function createClaudeSessionPublication(input: { events: ClaudeSession['events'] unbindReadingControl?: () => void process: AgentSessionAcquisition['process'] - linkId?: string - observedAt: number options?: ReadonlyMap }): { acquisition: AgentSessionAcquisition; session: ClaudeSession } { + const { deps } = input + const acquisitionGeneration = mintClaudeAcquisitionGeneration(deps) + const linkId = deps.mintLinkId?.() return { acquisition: { process: input.process, @@ -36,18 +45,20 @@ export function createClaudeSessionPublication(input: { leafUuid: input.leafUuid, resumed: input.continuesChain, fence: input.fence, - ...(input.linkId ? { linkId: input.linkId } : {}), - observedAt: input.observedAt + ...(linkId ? { linkId } : {}), + observedAt: deps.now?.() ?? Date.now() }), - acquisitionGeneration: input.acquisitionGeneration + acquisitionGeneration }, session: { connection: input.connection, + sessionId: input.sessionId, + logger: deps.logger, providerSessionId: input.providerSessionId, leafUuid: input.leafUuid, turnEndLeafUuid: input.turnEndLeafUuid, fence: input.fence, - acquisitionGeneration: input.acquisitionGeneration, + acquisitionGeneration, prompts: input.prompts, dispatchWaiters: [], retiredDispatchWaiters: [], diff --git a/src/main/claude/claude-structured-session-reading-control.test.ts b/src/main/claude/claude-structured-session-reading-control.test.ts index d90e5538964e..4cb12a0c41b9 100644 --- a/src/main/claude/claude-structured-session-reading-control.test.ts +++ b/src/main/claude/claude-structured-session-reading-control.test.ts @@ -100,7 +100,7 @@ describe('Claude structured reading control', () => { // The child exits before publish, so only the failed acquisition can release the binding. const claude = fakeClaude() const open = claude.openConnection - claude.openConnection = async (launch, handlers = {}) => { + claude.openConnection = async (launch, handlers) => { const connection = await open(launch, handlers) claude.connections[0].closed = true handlers.onExit?.(new Error('claude stream-json exited (code 1)')) diff --git a/src/main/claude/claude-structured-session-recovery.test.ts b/src/main/claude/claude-structured-session-recovery.test.ts index 71a7ac9ce319..d276908d7ed6 100644 --- a/src/main/claude/claude-structured-session-recovery.test.ts +++ b/src/main/claude/claude-structured-session-recovery.test.ts @@ -13,6 +13,9 @@ import { tick } from './claude-structured-session-test-support' import { invokeCanUseTool } from './claude-can-use-tool-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger describe('ClaudeStructuredSessionAdapter close and exit recovery', () => { it('shares concurrent close finalization and emits lifecycle once', async () => { @@ -57,6 +60,7 @@ describe('ClaudeStructuredSessionAdapter close and exit recovery', () => { const events: ClaudeStructuredSessionEvent[] = [] const callbackError = new Error('handle delivery failed') const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, @@ -325,6 +329,7 @@ describe('ClaudeStructuredSessionAdapter close and exit recovery', () => { } ) const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch, openConnection: claude.openConnection, onEvent: (event) => events.push(event), diff --git a/src/main/claude/claude-structured-session-state.ts b/src/main/claude/claude-structured-session-state.ts index d61df04ac75c..f907acc1d86a 100644 --- a/src/main/claude/claude-structured-session-state.ts +++ b/src/main/claude/claude-structured-session-state.ts @@ -26,6 +26,7 @@ import type { ClaudeChildWorkDecoder } from './claude-child-work-decoder' import type { ClaudeSlashCommandCatalog } from './claude-slash-command-catalog' import type { ClaudeAtRestCommandCatalog } from './claude-at-rest-commands' import type { ClaudeSessionStartup } from './claude-structured-session-startup-state' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' export type ClaudeAuthDiagnostic = { apiKeySourceConfigured: boolean @@ -124,6 +125,8 @@ export type ClaudeStructuredSessionAdapterDeps = { }) => Promise /** Host model catalog; sessions write their listings through. */ modelCatalog?: AgentModelCatalogStore + /** Where a failure this adapter carries on past is reported: the host's logger. */ + logger: StructuredAgentSessionLogger } export type ClaudeDispatchWaiter = { @@ -149,6 +152,10 @@ export type ClaudeDispatchWaiter = { export type ClaudeSession = { connection: ClaudeStreamJsonConnection + /** The Orca chat this child serves. */ + sessionId: string + /** The adapter's logger, for a step on this session that carries on past a failure. */ + logger: StructuredAgentSessionLogger providerSessionId: string /** Latest main-chain message seen on the live stream, mid-turn included. */ leafUuid: string | null @@ -207,7 +214,9 @@ export type ClaudeSession = { startup: ClaudeSessionStartup } -export function mintClaudeAcquisitionGeneration(deps: ClaudeStructuredSessionAdapterDeps): string { +export function mintClaudeAcquisitionGeneration( + deps: Pick +): string { return deps.mintAcquisitionGeneration?.() ?? randomUUID() } diff --git a/src/main/claude/claude-structured-session-test-support.ts b/src/main/claude/claude-structured-session-test-support.ts index dd7ad1e8d8c5..65bdfff6db5d 100644 --- a/src/main/claude/claude-structured-session-test-support.ts +++ b/src/main/claude/claude-structured-session-test-support.ts @@ -15,6 +15,10 @@ import { type ClaudeStructuredSessionEvent } from './claude-structured-session-adapter' import type { StructuredAgentSessionEventSink } from '../native-chat/agent-session-wire/structured-agent-session-event-sink' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +/** The logger every adapter built here reports to; spy on it to read what was reported. */ +export const CLAUDE_ADAPTER_TEST_LOGGER = recordingStructuredAgentSessionLogger().logger export const PROVIDER_SESSION_ID = '819cf9f8-e43c-4ad7-b50f-54aa158a726a' @@ -83,7 +87,7 @@ export function fakeClaude( const route = routes[subtype] return route ? route(params) : undefined } - const openConnection: typeof openClaudeStreamJsonConnection = async (launch, handlers = {}) => { + const openConnection: typeof openClaudeStreamJsonConnection = async (launch, handlers) => { let cycleInitEmitted = false // Keys mirror the real system/init frame, which carries `model` but no // effort of any kind: the current effort only comes back from get_settings. @@ -264,6 +268,7 @@ export function adapterAtPublishFor( onDispatchSettledLate?: ClaudeStructuredSessionAdapterDeps['onDispatchSettledLate'] ): ClaudeStructuredSessionAdapter { return new ClaudeStructuredSessionAdapter({ + logger: CLAUDE_ADAPTER_TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/claude/claude-structured-turn-resume-point.test.ts b/src/main/claude/claude-structured-turn-resume-point.test.ts index 4cb72eaa53a6..fb63e2666cf2 100644 --- a/src/main/claude/claude-structured-turn-resume-point.test.ts +++ b/src/main/claude/claude-structured-turn-resume-point.test.ts @@ -20,6 +20,9 @@ import { recordingJournalSink, tick } from './claude-structured-session-test-support' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const FENCE = 7 @@ -58,6 +61,7 @@ async function liveOwner( const events: ClaudeStructuredSessionEvent[] = [] const persistedHandles: unknown[] = [] const adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: { resume: PROVIDER_SESSION_ID }, @@ -138,6 +142,7 @@ describe('Claude durable resume point at turn end', () => { expect(head).toMatchObject({ leafUuid: 'a2' }) const resolve = createClaudeStructuredLaunchResolver({ + logger: TEST_LOGGER, // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: the resolver reads only getRecord from its store. store: { getRecord: () => store.record } as unknown as AgentSessionRecordStore, resolveWorkspacePath: async (id) => `/repos/${id}`, @@ -168,7 +173,7 @@ describe('Claude durable resume point at turn end', () => { }) it('never fails or holds up a turn when the write fails', async () => { - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const warn = vi.spyOn(TEST_LOGGER, 'warn') const persist = vi.fn(async () => { throw new Error('record write failed') }) @@ -180,8 +185,12 @@ describe('Claude durable resume point at turn end', () => { events.filter((event) => event.type === 'message' && event.message.type === 'result') ).toHaveLength(2) expect(warn).toHaveBeenCalledWith( - '[claude-resume-point] turn-end resume point was not persisted:', - expect.objectContaining({ leafUuid: 'a2' }) + 'the turn-end resume point was not persisted', + expect.objectContaining({ + scope: 'claude-resume-point-persist', + sessionId: 'session-1', + leafUuid: 'a2' + }) ) await expect(adapter.closeSession('session-1')).resolves.toBe(true) expect(persistedHandles).toEqual([expect.objectContaining({ leafUuid: 'a2' })]) diff --git a/src/main/claude/claude-supervised-stop-real-cli.test.ts b/src/main/claude/claude-supervised-stop-real-cli.test.ts index 82432e3fd6e6..d6ba7a2c9c45 100644 --- a/src/main/claude/claude-supervised-stop-real-cli.test.ts +++ b/src/main/claude/claude-supervised-stop-real-cli.test.ts @@ -14,6 +14,7 @@ import { CLAUDE_STRUCTURED_BASE_OPTIONS, claudeStructuredPermissionOptions } from './claude-structured-launch-resolution' +import { testEventSinkLogging } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' // Opt-in only: spends a real (haiku) turn per case. Run it in an isolated HOME with // ORCA_REAL_CLAUDE_BIN set, and ORCA_REAL_CLAUDE_SETTINGS when auth lives in a settings file. @@ -96,7 +97,7 @@ async function open(sessionId: string, cwd: string, resume: boolean, frames: Fra }, cwd }, - { onMessage: (message) => frames.push({ at: Date.now(), message }) } + { ...testEventSinkLogging(), onMessage: (message) => frames.push({ at: Date.now(), message }) } ) connections.push(connection) recordedPids.add(connection.pid!) diff --git a/src/main/codex/codex-collab-call-frames-fixture.ts b/src/main/codex/codex-collab-call-frames-fixture.ts index 8926e46dcca9..14b747e6e3de 100644 --- a/src/main/codex/codex-collab-call-frames-fixture.ts +++ b/src/main/codex/codex-collab-call-frames-fixture.ts @@ -5,6 +5,9 @@ import type { AgentJournalRenderItem } from '../../shared/agent-session-journal- import type { StructuredAgentSessionEventSink } from '../native-chat/agent-session-wire/structured-agent-session-event-sink' import { fakeCodex, identityFor, THREAD_ID } from './codex-structured-session-adapter-fixture' import { CodexStructuredSessionAdapter } from './codex-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger // Shapes as a live default-mode session sent them (codex-cli 0.157); only the sender is remapped. export const HELPER = '01a0ea72-80bc-7632-a97f-4a9a0d50d08f' @@ -80,6 +83,7 @@ export const waitStarted = collab('item/started', { export async function publishedRows(frames: Frame[]): Promise { const codex = fakeCodex() const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-default-mode-subagents.test.ts b/src/main/codex/codex-default-mode-subagents.test.ts index 335f903efbbf..4684bdf2ccf6 100644 --- a/src/main/codex/codex-default-mode-subagents.test.ts +++ b/src/main/codex/codex-default-mode-subagents.test.ts @@ -18,6 +18,9 @@ import { createCodexJournalTranslator } from './codex-structured-journal-transla import { CodexSubagentExecutions } from './codex-subagent-executions' import { readCodexSubagentAnnouncements } from './codex-subagent-activity' import type { CodexThreadItem } from './codex-thread-item-identity' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const parent = makeStructuredAgentStatusSubject( { @@ -141,6 +144,7 @@ async function session() { mintChildWorkId: () => `child-${++minted}` }) const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-acquisition-exit-proof.test.ts b/src/main/codex/codex-structured-acquisition-exit-proof.test.ts index f0737fc36a36..60ba82b25969 100644 --- a/src/main/codex/codex-structured-acquisition-exit-proof.test.ts +++ b/src/main/codex/codex-structured-acquisition-exit-proof.test.ts @@ -3,6 +3,9 @@ import { describe, expect, it, vi } from 'vitest' import type { AgentSessionJournalIdentity } from '../../shared/agent-session-journal-types' import type { CodexAppServerConnection } from './codex-app-server-connection-types' import { CodexStructuredSessionAdapter } from './codex-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const IDENTITY: AgentSessionJournalIdentity = { sessionId: 'session-1', @@ -32,6 +35,7 @@ describe('Codex failed-acquisition exit proof', () => { connection }) const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], @@ -70,6 +74,7 @@ describe('Codex failed-acquisition exit proof', () => { close } const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], @@ -102,6 +107,7 @@ describe('Codex failed-acquisition exit proof', () => { close } const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], @@ -140,6 +146,7 @@ describe('Codex failed-acquisition exit proof', () => { close } const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-child-environment.test.ts b/src/main/codex/codex-structured-child-environment.test.ts index 4dcd49e96459..7ad3a20a8b75 100644 --- a/src/main/codex/codex-structured-child-environment.test.ts +++ b/src/main/codex/codex-structured-child-environment.test.ts @@ -8,6 +8,9 @@ import { structuredWorkerIdentities, structuredWorkerProcessIncarnation } from '../runtime/structured-worker-identity' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const DEV_CLI_BIN_FIRST = /^[^:;]*[\\/]cli[\\/]bin[:;]/ // The dev launcher by absolute path: a login shell's profile cannot reorder it behind a global. @@ -26,7 +29,8 @@ describe('buildCodexStructuredChildEnvironment', () => { env: { EXAMPLE_GATEWAY_TOKEN: 'shell-exported', CODEX_HOME: '/shell/home' } }, 'spawn-token', - 'session-not-a-worker' + 'session-not-a-worker', + TEST_LOGGER ) ).toEqual({ EXAMPLE_GATEWAY_TOKEN: 'shell-exported', @@ -51,7 +55,9 @@ describe('buildCodexStructuredChildEnvironment', () => { env: {} } const sessionId = 'a1b2c3d4-e5f6-4a7b-8c9d-0e1f2a3b4c5d' - expect(buildCodexStructuredChildEnvironment(launch, 'spawn-token', sessionId)).toEqual({ + expect( + buildCodexStructuredChildEnvironment(launch, 'spawn-token', sessionId, TEST_LOGGER) + ).toEqual({ [CODEX_SPAWN_TOKEN_ENV]: 'spawn-token', // Not a worker, so no handle: the id alone names this chat as a caller. ORCA_AGENT_SESSION_ID: sessionId, @@ -72,7 +78,12 @@ describe('buildCodexStructuredChildEnvironment', () => { hostScope: { kind: 'local', hostId: 'local' } }) try { - const env = buildCodexStructuredChildEnvironment(launch, 'spawn-token', sessionId) + const env = buildCodexStructuredChildEnvironment( + launch, + 'spawn-token', + sessionId, + TEST_LOGGER + ) expect(env.ORCA_TERMINAL_HANDLE).toBe(handle) expect(env.ORCA_AGENT_SESSION_ID).toBe(sessionId) expect(env.ORCA_CLI_COMMAND).toMatch(DEV_CLI_LAUNCHER) @@ -124,7 +135,8 @@ describe('the spawned Codex child', () => { env: {} }, 'spawn-token', - sessionId + sessionId, + TEST_LOGGER ) const connection = await openCodexAppServerConnection({ command: process.execPath, diff --git a/src/main/codex/codex-structured-child-environment.ts b/src/main/codex/codex-structured-child-environment.ts index 38ea91abe268..201c00d4005d 100644 --- a/src/main/codex/codex-structured-child-environment.ts +++ b/src/main/codex/codex-structured-child-environment.ts @@ -1,18 +1,24 @@ import type { CodexStructuredLaunch } from './codex-structured-session-state' import { CODEX_SPAWN_TOKEN_ENV } from './codex-structured-owner-identity' import { structuredSessionChildIdentityEnv } from '../runtime/structured-session-child-identity-env' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' export function buildCodexStructuredChildEnvironment( launch: CodexStructuredLaunch, spawnToken: string, - sessionId: string + sessionId: string, + logger: StructuredAgentSessionLogger ): Record { return { // Every structured session speaks orchestration as itself: its injected id and the Orca CLI. - ...structuredSessionChildIdentityEnv(sessionId, { - ...launch.env, - ...(launch.codexHome ? { CODEX_HOME: launch.codexHome } : {}) - }), + ...structuredSessionChildIdentityEnv( + sessionId, + { + ...launch.env, + ...(launch.codexHome ? { CODEX_HOME: launch.codexHome } : {}) + }, + logger + ), [CODEX_SPAWN_TOKEN_ENV]: spawnToken } } diff --git a/src/main/codex/codex-structured-child-work-producer.test.ts b/src/main/codex/codex-structured-child-work-producer.test.ts index 4317b5669d77..4cee1119c923 100644 --- a/src/main/codex/codex-structured-child-work-producer.test.ts +++ b/src/main/codex/codex-structured-child-work-producer.test.ts @@ -26,6 +26,9 @@ import { makeStructuredAgentStatusSubject } from '../../shared/agent-status-subj import type { StructuredAgentSessionEventSink } from '../native-chat/agent-session-wire/structured-agent-session-event-sink' import { fakeCodex, identityFor, THREAD_ID } from './codex-structured-session-adapter-fixture' import { CodexStructuredSessionAdapter } from './codex-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const parent = makeStructuredAgentStatusSubject( { @@ -105,6 +108,7 @@ async function producer() { ) }) const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-dispatch-test-support.ts b/src/main/codex/codex-structured-dispatch-test-support.ts index 7513ec1fbbe4..9813f7fbdc3e 100644 --- a/src/main/codex/codex-structured-dispatch-test-support.ts +++ b/src/main/codex/codex-structured-dispatch-test-support.ts @@ -14,6 +14,9 @@ import type { StructuredAgentSessionEventSink } from '../native-chat/agent-sessi import { CodexStructuredSessionAdapter } from './codex-structured-session-adapter' import { codexTurnLifecycleFake } from './codex-turn-lifecycle-fake' import type { CodexStructuredSessionAdapterDeps } from './codex-structured-session-state' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger export const CODEX_TEST_THREAD_ID = 'thread-abc' @@ -96,6 +99,7 @@ export async function acquiredCodexAdapter(input: { requestTimeoutMs?: number }): Promise { const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-session-acquire.ts b/src/main/codex/codex-structured-session-acquire.ts index 37c34a4bf3a1..7f746bbc8464 100644 --- a/src/main/codex/codex-structured-session-acquire.ts +++ b/src/main/codex/codex-structured-session-acquire.ts @@ -126,7 +126,12 @@ export async function acquireCodexStructuredSession(input: { command: launch.command, args: launch.args, cwd: launch.cwd, - env: buildCodexStructuredChildEnvironment(launch, acquireInput.spawnToken, sessionId) + env: buildCodexStructuredChildEnvironment( + launch, + acquireInput.spawnToken, + sessionId, + deps.logger + ) }, { onNotification: (method, params) => { diff --git a/src/main/codex/codex-structured-session-adapter-fixture.ts b/src/main/codex/codex-structured-session-adapter-fixture.ts index f2b4e102c355..a6a1938360e5 100644 --- a/src/main/codex/codex-structured-session-adapter-fixture.ts +++ b/src/main/codex/codex-structured-session-adapter-fixture.ts @@ -14,6 +14,9 @@ import { type CodexStructuredSessionEvent } from './codex-structured-session-adapter' import type { CodexStructuredSessionAdapterDeps } from './codex-structured-session-state' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger export const THREAD_ID = 'thread-abc' @@ -111,6 +114,7 @@ export function adapterFor( ): CodexStructuredSessionAdapter { let acquisitionGeneration = 0 return new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-session-adapter-lifecycle.test.ts b/src/main/codex/codex-structured-session-adapter-lifecycle.test.ts index e3211f320e85..2fe718f2708b 100644 --- a/src/main/codex/codex-structured-session-adapter-lifecycle.test.ts +++ b/src/main/codex/codex-structured-session-adapter-lifecycle.test.ts @@ -16,6 +16,9 @@ import { type CodexStructuredLaunch, type CodexStructuredSessionEvent } from './codex-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const THREAD_ID = 'thread-abc' @@ -102,6 +105,7 @@ function adapterFor( ): CodexStructuredSessionAdapter { let acquisitionGeneration = 0 return new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-session-adapter.test.ts b/src/main/codex/codex-structured-session-adapter.test.ts index 70b2ecd7147a..3c3bc8a96937 100644 --- a/src/main/codex/codex-structured-session-adapter.test.ts +++ b/src/main/codex/codex-structured-session-adapter.test.ts @@ -20,6 +20,9 @@ import { fakeCodex, identityFor } from './codex-structured-session-adapter-fixture' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger describe('CodexStructuredSessionAdapter.acquire', () => { it('starts a new thread and reports the process and link the lease will prove', async () => { @@ -239,6 +242,7 @@ describe('CodexStructuredSessionAdapter.acquire', () => { it('refuses to publish a session whose child died while it was being acquired', async () => { const codex = fakeCodex() const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], @@ -271,6 +275,7 @@ describe('CodexStructuredSessionAdapter.acquire', () => { it('classifies launch validation failure as pre-spawn without opening a child', async () => { const codex = fakeCodex() const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => { throw new Error('workspace no longer exists') }, @@ -316,6 +321,7 @@ describe('CodexStructuredSessionAdapter.acquire', () => { return codex.openConnection(...args) } const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], @@ -345,6 +351,7 @@ describe('CodexStructuredSessionAdapter.acquire', () => { const launch = Promise.withResolvers() const codex = fakeCodex() const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: () => launch.promise, openConnection: codex.openConnection, readProcessStartTime: async () => 1_700_000_000_000 diff --git a/src/main/codex/codex-structured-session-background-tasks.test.ts b/src/main/codex/codex-structured-session-background-tasks.test.ts index 4e2515da7d43..b3e163e35b8c 100644 --- a/src/main/codex/codex-structured-session-background-tasks.test.ts +++ b/src/main/codex/codex-structured-session-background-tasks.test.ts @@ -10,6 +10,9 @@ import { CodexStructuredSessionAdapter } from './codex-structured-session-adapte import { CodexBackgroundTaskTracker } from './codex-background-task-tracker' import type { CodexStructuredSessionEvent } from './codex-structured-session-state' import type { StructuredAgentSessionEventSink } from '../native-chat/agent-session-wire/structured-agent-session-event-sink' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger // Proves the host's child records are actually REACHED from provider traffic: the tracker is // unit-tested separately, and a producer that is correct but unwired publishes nothing while @@ -85,6 +88,7 @@ async function adapterWithSession( ): Promise<{ adapter: CodexStructuredSessionAdapter; codex: ReturnType }> { const codex = fakeCodex(close) const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-session-cancel.test.ts b/src/main/codex/codex-structured-session-cancel.test.ts index cd30bfa2e6d1..4edcf9f0c139 100644 --- a/src/main/codex/codex-structured-session-cancel.test.ts +++ b/src/main/codex/codex-structured-session-cancel.test.ts @@ -47,6 +47,9 @@ import { type CodexStructuredSessionAdapterDeps, type CodexStructuredSessionEvent } from './codex-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const THREAD_ID = 'thread-abc' const USER_MESSAGE: AgentJournalMessageItem = { @@ -113,6 +116,7 @@ async function acquired( overrides: Partial> = {} ): Promise { const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-session-close.test.ts b/src/main/codex/codex-structured-session-close.test.ts index 9d80a0fa9829..6b5374f58b55 100644 --- a/src/main/codex/codex-structured-session-close.test.ts +++ b/src/main/codex/codex-structured-session-close.test.ts @@ -17,6 +17,9 @@ import { CodexPromptRegistry } from './codex-structured-prompt-replies' import type { CodexSession } from './codex-structured-session-state' import type { StructuredAgentSessionAdapter } from '../native-chat/agent-session-wire/structured-agent-session-adapter' import { StructuredAgentSessionAdapterRouter } from '../native-chat/agent-session-wire/structured-agent-session-adapter-router' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const THREAD = 'thread-1' @@ -51,6 +54,7 @@ function adapterFixture() { return connection }) as typeof openCodexAppServerConnection const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ command: 'codex', args: ['app-server'], diff --git a/src/main/codex/codex-structured-session-shutdown.test.ts b/src/main/codex/codex-structured-session-shutdown.test.ts index 3883dad4600e..091a2272ce6c 100644 --- a/src/main/codex/codex-structured-session-shutdown.test.ts +++ b/src/main/codex/codex-structured-session-shutdown.test.ts @@ -8,6 +8,9 @@ import { CodexStructuredSessionAdapter, type CodexStructuredLaunch } from './codex-structured-session-adapter' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION_ID = 'session-1' const THREAD_ID = 'thread-1' @@ -49,6 +52,7 @@ describe('CodexStructuredSessionAdapter shutdown', () => { const firstLaunch = Promise.withResolvers() let launchCount = 0 const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: () => { launchCount += 1 return launchCount === 1 ? firstLaunch.promise : Promise.resolve(LAUNCH) @@ -88,6 +92,7 @@ describe('CodexStructuredSessionAdapter shutdown', () => { close }) satisfies CodexAppServerConnection) as typeof openCodexAppServerConnection const adapter = new CodexStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => LAUNCH, openConnection, readProcessStartTime: async () => 1_700_000_000_000 diff --git a/src/main/codex/codex-structured-session-state.ts b/src/main/codex/codex-structured-session-state.ts index a47cb5a78fe2..cb9adc65f4b6 100644 --- a/src/main/codex/codex-structured-session-state.ts +++ b/src/main/codex/codex-structured-session-state.ts @@ -20,6 +20,7 @@ import type { CodexBackgroundTaskTracker } from './codex-background-task-tracker import type { CodexJournalTranslator } from './codex-structured-journal-translation' import type { StructuredAgentSessionEndedEvent } from '../native-chat/agent-session-wire/structured-agent-session-adapter' import type { CodexStructuredPermissionPolicy } from './codex-structured-permission-policy' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' import type { AgentModelCatalogSessionAccess, AgentModelCatalogStore @@ -98,6 +99,8 @@ export type CodexStructuredSessionAdapterDeps = { requestTimeoutMs?: number /** Host model catalog; sessions write their listings through and read back. */ modelCatalog?: AgentModelCatalogStore + /** Where a failure this adapter carries on past is reported: the host's logger. */ + logger: StructuredAgentSessionLogger } export type CodexSession = { diff --git a/src/main/native-chat/agent-session-journal/journal-database-records-migration.test.ts b/src/main/native-chat/agent-session-journal/journal-database-records-migration.test.ts index 120588b306dd..a2ec96499c35 100644 --- a/src/main/native-chat/agent-session-journal/journal-database-records-migration.test.ts +++ b/src/main/native-chat/agent-session-journal/journal-database-records-migration.test.ts @@ -16,6 +16,9 @@ import { } from './journal-database' import { createJournalTablesSql } from './journal-database-schema' import { journalDatabasePath } from './journal-host-database' +import { recordingStructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger let root: string let dbPath: string @@ -82,7 +85,7 @@ describe('the version-4 migration', () => { seedVersion3() const copy = importOf('session-a') - const opened = openJournalDatabase(dbPath, copy) + const opened = openJournalDatabase(dbPath, copy, TEST_LOGGER) opened.db.close() expect(opened).toMatchObject({ readOnly: false, legacyRecordImportOwed: false }) @@ -96,10 +99,10 @@ describe('the version-4 migration', () => { it('never runs the copy again once the database is at 4', () => { seedVersion3() - openJournalDatabase(dbPath, importOf('session-a')).db.close() + openJournalDatabase(dbPath, importOf('session-a'), TEST_LOGGER).db.close() const again = importOf('session-b') - openJournalDatabase(dbPath, again).db.close() + openJournalDatabase(dbPath, again, TEST_LOGGER).db.close() expect(again.runs).toBe(0) inspect((db) => expect(recordIds(db)).toEqual(['session-a'])) @@ -119,7 +122,7 @@ describe('the version-4 migration', () => { return original.call(this, sql, options) }) - expect(() => openJournalDatabase(dbPath, importOf('session-a'))).toThrow( + expect(() => openJournalDatabase(dbPath, importOf('session-a'), TEST_LOGGER)).toThrow( 'crash before the version is published' ) pragma.mockRestore() @@ -129,7 +132,7 @@ describe('the version-4 migration', () => { }) const retry = importOf('session-a') - openJournalDatabase(dbPath, retry).db.close() + openJournalDatabase(dbPath, retry, TEST_LOGGER).db.close() expect(retry.runs).toBe(1) inspect((db) => { expect(journalPragmaNumber(db, 'user_version')).toBe(4) @@ -140,7 +143,7 @@ describe('the version-4 migration', () => { it('makes the tables but keeps the copy owed when the records file could not be read', () => { seedVersion3() - const opened = openJournalDatabase(dbPath, { owed: true }) + const opened = openJournalDatabase(dbPath, { owed: true }, TEST_LOGGER) // A chat created while the copy is owed keeps its row through the copy that follows. opened.db .prepare("INSERT INTO agent_session_records (session_id, record_json) VALUES ('new', '{}')") @@ -149,7 +152,7 @@ describe('the version-4 migration', () => { expect(opened.legacyRecordImportOwed).toBe(true) inspect((db) => expect(journalPragmaNumber(db, 'user_version')).toBe(3)) - openJournalDatabase(dbPath, importOf('session-a')).db.close() + openJournalDatabase(dbPath, importOf('session-a'), TEST_LOGGER).db.close() inspect((db) => { expect(journalPragmaNumber(db, 'user_version')).toBe(4) expect(recordIds(db)).toEqual(['new', 'session-a']) @@ -157,7 +160,7 @@ describe('the version-4 migration', () => { }) it('stamps a fresh file with the released version while the copy is owed', () => { - openJournalDatabase(dbPath, { owed: true }).db.close() + openJournalDatabase(dbPath, { owed: true }, TEST_LOGGER).db.close() inspect((db) => { expect(journalPragmaNumber(db, 'user_version')).toBe(3) @@ -173,7 +176,7 @@ describe('the version-4 migration', () => { }) it('creates every table on a fresh file at version 4', () => { - openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db.close() + openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db.close() inspect((db) => { expect(journalPragmaNumber(db, 'user_version')).toBe(4) @@ -208,7 +211,7 @@ function openAsVersion3Build(path: string): { db: Database.Database; readOnly: b describe('a build from before the move', () => { it('opens a version-4 database read-only, so it never writes beside the records', () => { - openJournalDatabase(dbPath, importOf('session-a')).db.close() + openJournalDatabase(dbPath, importOf('session-a'), TEST_LOGGER).db.close() const older = openAsVersion3Build(dbPath) try { diff --git a/src/main/native-chat/agent-session-journal/journal-database.test.ts b/src/main/native-chat/agent-session-journal/journal-database.test.ts index 677efc21c4d7..b0703ac2b9d1 100644 --- a/src/main/native-chat/agent-session-journal/journal-database.test.ts +++ b/src/main/native-chat/agent-session-journal/journal-database.test.ts @@ -26,6 +26,9 @@ import { } from './journal-row-table' import type { JournalRow } from './journal-row-schema' import { AGENT_SESSION_JOURNAL_SCHEMA_VERSION } from '../../../shared/agent-session-journal-types' +import { recordingStructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger let root: string let dbPath: string @@ -67,7 +70,7 @@ afterEach(async () => { describe('the host journal database open', () => { it('creates every table and reads back every load-bearing pragma', () => { - const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db + const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db try { const tables = db .prepare("SELECT name FROM sqlite_master WHERE type = 'table' ORDER BY name") @@ -98,14 +101,14 @@ describe('the host journal database open', () => { // T5: a newer build's database opens read-only, its rows readable, and is left byte-identical. it('opens a newer user_version read-only without touching the file', async () => { - const seeded = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db + const seeded = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db publishJournalSessionEpoch(seeded, SESSION, 'epoch-1') insertJournalRow(seeded, 'session-1', epochRow(1)) seeded.pragma(`user_version = ${JOURNAL_DB_SCHEMA_VERSION + 5}`) seeded.close() const before = await digest(dbPath) - const opened = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS) + const opened = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER) try { expect(opened.readOnly).toBe(true) expect(readJournalSessionEpoch(opened.db, 'session-1')).toBe('epoch-1') @@ -122,7 +125,7 @@ describe('the host journal database open', () => { it('closes the raw connection when schema setup throws', async () => { const failing = join(root, 'nested', 'agent-session-journal.db') - expect(() => openJournalDatabase(failing, NO_LEGACY_JOURNAL_RECORDS)).toThrow() + expect(() => openJournalDatabase(failing, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER)).toThrow() await expect(stat(`${failing}-wal`)).rejects.toThrow() await expect(rm(root, { recursive: true, force: true })).resolves.toBeUndefined() root = await mkdtemp(join(tmpdir(), 'orca-journal-db-')) @@ -131,7 +134,7 @@ describe('the host journal database open', () => { describe('journal row statements', () => { it('serves replay, resume, suffix truncation and an epoch discard', () => { - const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db + const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db try { db.exec('BEGIN IMMEDIATE') for (let seq = 1; seq <= 5; seq += 1) { @@ -162,7 +165,7 @@ describe('journal row statements', () => { }) it('deletes only the rows no pointer names', () => { - const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db + const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db try { insertJournalRow(db, 'session-1', epochRow(1, 'epoch-copying')) insertJournalRow(db, 'session-2', epochRow(1, 'epoch-live')) @@ -181,7 +184,7 @@ describe('journal row statements', () => { }) it('refuses a duplicate sequence inside one epoch of one chat', () => { - const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db + const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db try { insertJournalRow(db, 'session-1', epochRow(1)) expect(() => insertJournalRow(db, 'session-1', epochRow(1))).toThrow() @@ -193,7 +196,7 @@ describe('journal row statements', () => { }) it('moves the epoch pointer in place', () => { - const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS).db + const db = openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db try { publishJournalSessionEpoch(db, SESSION, 'epoch-1') publishJournalSessionEpoch(db, SESSION, 'epoch-2') @@ -221,7 +224,7 @@ describe('schema creation', () => { return original.call(this, sql, options) }) - expect(() => openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS)).toThrow( + expect(() => openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER)).toThrow( 'crash before the version is published' ) pragma.mockRestore() @@ -253,10 +256,10 @@ INSERT INTO journal_sessions VALUES ('s1', 'ws', 'e1', 0, NULL, NULL);`) earlier.close() const before = await digest(dbPath) - expect(() => openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS)).toThrow( + expect(() => openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER)).toThrow( `unreleased schema ${version}` ) - expect(() => openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS)).toThrow( + expect(() => openJournalDatabase(dbPath, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER)).toThrow( JournalUnreleasedSchemaError ) diff --git a/src/main/native-chat/agent-session-journal/journal-database.ts b/src/main/native-chat/agent-session-journal/journal-database.ts index a306ad6e564e..69edab3ca2eb 100644 --- a/src/main/native-chat/agent-session-journal/journal-database.ts +++ b/src/main/native-chat/agent-session-journal/journal-database.ts @@ -15,6 +15,7 @@ import { } from './journal-database-schema' import { JournalUnreleasedSchemaError } from './journal-open-failure' import { ensureQueuedMessagesTable } from './queued-message-schema' +import type { StructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger' export const JOURNAL_BUSY_TIMEOUT_MS = 5000 /** Bounds the WAL a checkpoint leaves behind; SQLite truncates it back to this after a reset. */ @@ -98,7 +99,8 @@ export function journalDatabaseHoldsAgentSessions(dbPath: string): boolean | und export function openJournalDatabase( dbPath: string, - legacyRecords: JournalLegacyRecordImport + legacyRecords: JournalLegacyRecordImport, + logger: StructuredAgentSessionLogger ): OpenJournalDatabase { const probe = new Database(dbPath) let stored: number @@ -125,7 +127,7 @@ export function openJournalDatabase( ) } configureJournalPragmas(probe, stored) - const legacyRecordImportOwed = migrateJournalSchema(probe, stored, legacyRecords) + const legacyRecordImportOwed = migrateJournalSchema(probe, stored, legacyRecords, logger) // Outside `migrateJournalSchema` on purpose: its early return skips a db // already at the current version, and this table must exist at EVERY // writable open with no `user_version` bump (see `ensureQueuedMessagesTable`). @@ -167,12 +169,13 @@ function configureJournalPragmas(db: Database.Database, stored: number): void { function migrateJournalSchema( db: Database.Database, stored: number, - legacyRecords: JournalLegacyRecordImport + legacyRecords: JournalLegacyRecordImport, + logger: StructuredAgentSessionLogger ): boolean { if (stored >= JOURNAL_DB_SCHEMA_VERSION) { return false } - runJournalTransaction(db, () => { + runJournalTransaction(db, logger, () => { if (stored === 0) { db.exec(createJournalTablesSql()) } @@ -199,6 +202,7 @@ function migrateJournalSchema( */ export function runJournalTransaction( db: Database.Database, + logger: StructuredAgentSessionLogger, run: (db: Database.Database) => T, onStranded: () => void = () => undefined ): T { @@ -215,10 +219,10 @@ export function runJournalTransaction( try { db.exec('ROLLBACK') } catch (rollbackError) { - console.warn( - '[agent-session-journal] rolling back a failed transaction failed', - rollbackError - ) + logger.warn('rolling back a failed chat journal transaction failed', { + scope: 'journal-transaction-rollback', + error: rollbackError + }) onStranded() } } diff --git a/src/main/native-chat/agent-session-journal/journal-host-database-test-support.ts b/src/main/native-chat/agent-session-journal/journal-host-database-test-support.ts index dbe15b4709ed..e5665e71b185 100644 --- a/src/main/native-chat/agent-session-journal/journal-host-database-test-support.ts +++ b/src/main/native-chat/agent-session-journal/journal-host-database-test-support.ts @@ -17,16 +17,22 @@ import type Database from '../../sqlite/sync-database' import type { AgentSessionJournal } from './journal-store' import type { AgentSessionJournalOptions } from './journal-store-contracts' import { openAgentSessionJournal } from './journal-store-factory' +import type { StructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger-test-support' const opened = new Map() -export function openTestJournalHostDatabase(stateDirectory: string): JournalHostDatabase { +/** `logger` applies only to the open that creates this directory's database. */ +export function openTestJournalHostDatabase( + stateDirectory: string, + logger: StructuredAgentSessionLogger = recordingStructuredAgentSessionLogger().logger +): JournalHostDatabase { const directory = resolve(stateDirectory) const existing = opened.get(directory) if (existing && !existing.isClosed) { return existing } - const database = JournalHostDatabase.openWith(directory, NO_LEGACY_JOURNAL_RECORDS) + const database = JournalHostDatabase.openWith(directory, NO_LEGACY_JOURNAL_RECORDS, logger) opened.set(directory, database) return database } diff --git a/src/main/native-chat/agent-session-journal/journal-host-database.ts b/src/main/native-chat/agent-session-journal/journal-host-database.ts index ca6036d3a9d0..799c9ef8d0dd 100644 --- a/src/main/native-chat/agent-session-journal/journal-host-database.ts +++ b/src/main/native-chat/agent-session-journal/journal-host-database.ts @@ -21,6 +21,7 @@ import { import { journalOpenRefusalError } from './journal-open-failure' import { journalDirectoryFor } from './journal-paths' import { AgentSessionJournalError } from './journal-write-guards' +import type { StructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger' const JOURNAL_DATABASE_FILE = 'agent-session-journal.db' @@ -39,7 +40,9 @@ export class JournalHostDatabase { private constructor( readonly stateDirectory: string, - opened: OpenJournalDatabase + opened: OpenJournalDatabase, + /** The host's logger: every chat's journal reports a failure it carries on past here. */ + readonly logger: StructuredAgentSessionLogger ) { this.connection = opened.db this.readOnly = opened.readOnly @@ -49,7 +52,8 @@ export class JournalHostDatabase { /** `readLegacyRecords` runs only when this open migrates to version 4, before any transaction. */ static async open( stateDirectory: string, - readLegacyRecords: () => Promise + readLegacyRecords: () => Promise, + logger: StructuredAgentSessionLogger ): Promise { mkdirSync(stateDirectory, { recursive: true }) const migrates = journalDatabaseMigratesRecords( @@ -57,19 +61,22 @@ export class JournalHostDatabase { ) return JournalHostDatabase.openWith( stateDirectory, - migrates ? await readLegacyRecords() : NO_LEGACY_JOURNAL_RECORDS + migrates ? await readLegacyRecords() : NO_LEGACY_JOURNAL_RECORDS, + logger ) } /** The same open with the records file already read; tests pass `NO_LEGACY_JOURNAL_RECORDS`. */ static openWith( stateDirectory: string, - legacyRecords: JournalLegacyRecordImport + legacyRecords: JournalLegacyRecordImport, + logger: StructuredAgentSessionLogger ): JournalHostDatabase { mkdirSync(stateDirectory, { recursive: true }) return new JournalHostDatabase( stateDirectory, - openJournalDatabase(journalDatabasePath(stateDirectory), legacyRecords) + openJournalDatabase(journalDatabasePath(stateDirectory), legacyRecords, logger), + logger ) } @@ -90,7 +97,7 @@ export class JournalHostDatabase { /** One IMMEDIATE transaction; see `runJournalTransaction`. */ transaction(run: (db: Database.Database) => T): T { - return runJournalTransaction(this.db, run, () => { + return runJournalTransaction(this.db, this.logger, run, () => { this.stranded = true }) } diff --git a/src/main/native-chat/agent-session-journal/journal-open-failure.test.ts b/src/main/native-chat/agent-session-journal/journal-open-failure.test.ts index 787b1aa6491b..b8d49c55174f 100644 --- a/src/main/native-chat/agent-session-journal/journal-open-failure.test.ts +++ b/src/main/native-chat/agent-session-journal/journal-open-failure.test.ts @@ -16,6 +16,8 @@ import { journalDatabasePath } from './journal-host-database' import { replayJournal } from './journal-open' import { recordingStructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger-test-support' +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger + let root: string beforeEach(async () => { @@ -29,7 +31,11 @@ afterEach(async () => { /** What the journal's own open, then a chat's replay, throws for the file as it stands. */ function openFailure(): unknown { try { - const db = openJournalDatabase(journalDatabasePath(root), NO_LEGACY_JOURNAL_RECORDS).db + const db = openJournalDatabase( + journalDatabasePath(root), + NO_LEGACY_JOURNAL_RECORDS, + TEST_LOGGER + ).db try { replayJournal(db, 'session-1') } finally { @@ -60,7 +66,7 @@ describe('classifyJournalOpenFailure', () => { it('calls a journal whose pages are damaged corrupt', async () => { const path = journalDatabasePath(root) - const opened = openJournalDatabase(path, NO_LEGACY_JOURNAL_RECORDS).db + const opened = openJournalDatabase(path, NO_LEGACY_JOURNAL_RECORDS, TEST_LOGGER).db opened.exec('PRAGMA journal_mode = DELETE') opened.close() const bytes = await readFile(path) diff --git a/src/main/native-chat/agent-session-journal/journal-per-session-import.test.ts b/src/main/native-chat/agent-session-journal/journal-per-session-import.test.ts index 9ec154d0e5df..6e4351cb08bf 100644 --- a/src/main/native-chat/agent-session-journal/journal-per-session-import.test.ts +++ b/src/main/native-chat/agent-session-journal/journal-per-session-import.test.ts @@ -29,6 +29,7 @@ import { journalDirectoryFor, legacyJournalDatabaseFile } from './journal-paths' import { importPerSessionJournal } from './journal-per-session-import' import { readJournalSessionEpoch, type JournalStoredRow } from './journal-row-table' import { createStructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from '../agent-session-wire/structured-agent-session-logger-test-support' vi.mock('node:fs', async (importOriginal) => { const actual = await importOriginal() @@ -380,7 +381,7 @@ describe('importing a per-chat journal', () => { const { epoch, rows } = await historyRows() await writeLegacyJournal(epoch, rows) const database = openTestJournalHostDatabase(root) - const errors = vi.spyOn(console, 'error').mockImplementation(() => undefined) + const errors = vi.spyOn(database.logger, 'error') const input = { database, identity: IDENTITY, @@ -403,6 +404,10 @@ describe('importing a per-chat journal', () => { total: 0 }) expect(errors).toHaveBeenCalledOnce() + expect(errors.mock.calls[0]?.[1]).toMatchObject({ + scope: 'journal-import-verify', + sessionId: IDENTITY.sessionId + }) // A copy that reads back whole then imports it, over what the refused ones left. const journal = await openChat() expect(readTestJournalRows(database.db, IDENTITY.sessionId, epoch)).toEqual(rows) @@ -416,7 +421,7 @@ describe('importing a per-chat journal', () => { expect(rows.filter((row) => row.rowJson.includes('On it.'))).toHaveLength(1) await writeLegacyJournal(epoch, rows) const database = openTestJournalHostDatabase(root) - const errors = vi.spyOn(console, 'error').mockImplementation(() => undefined) + const errors = vi.spyOn(database.logger, 'error') const input = { database, identity: IDENTITY, @@ -441,6 +446,8 @@ describe('importing a per-chat journal', () => { await writeLegacyJournal(epoch, rows) removeFails() vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const logged = recordingStructuredAgentSessionLogger() + openTestJournalHostDatabase(root, logged.logger) const journal = await openChat() await journal.appendItem( @@ -449,6 +456,13 @@ describe('importing a per-chat journal', () => { { fence: 1, turnScope: AGENT_JOURNAL_THREAD_SCOPE } ) expect(existsSync(legacyJournalDatabaseFile(legacyDir()))).toBe(true) + expect(logged.entries.map(({ fields }) => fields)).toEqual([ + expect.objectContaining({ + scope: 'journal-import-retire', + sessionId: IDENTITY.sessionId, + legacyDirectory: legacyDir() + }) + ]) // The process exits and the database closes. await journals.closeAll() await removeWorks() diff --git a/src/main/native-chat/agent-session-journal/journal-per-session-import.ts b/src/main/native-chat/agent-session-journal/journal-per-session-import.ts index 5f85fdded437..6736da1a71a7 100644 --- a/src/main/native-chat/agent-session-journal/journal-per-session-import.ts +++ b/src/main/native-chat/agent-session-journal/journal-per-session-import.ts @@ -130,7 +130,7 @@ async function importOnce(input: ImportInput): Promise void = (path) => rmSync(path, { force: true }) ): void { const file = legacyJournalDatabaseFile(legacyDirectory) @@ -133,7 +136,12 @@ export function retireLegacyJournal( remove(path) } } catch (error) { - console.warn(`[agent-session-journal] deleting imported ${legacyDirectory} failed`, error) + logger.warn('deleting an imported per-chat journal failed', { + scope: 'journal-import-retire', + sessionId, + legacyDirectory, + error + }) return } try { diff --git a/src/main/native-chat/agent-session-journal/journal-queued-messages.ts b/src/main/native-chat/agent-session-journal/journal-queued-messages.ts index b8fcafc0b6c0..f0cb91fd19f6 100644 --- a/src/main/native-chat/agent-session-journal/journal-queued-messages.ts +++ b/src/main/native-chat/agent-session-journal/journal-queued-messages.ts @@ -293,9 +293,10 @@ export class JournalQueuedMessages { * never allowed to fail opening the chat. */ repairAndPruneAtOpen(): Promise { return this.repairAndPrune().catch((error: unknown) => { - console.warn('[journal-open] queued-message repair skipped:', { + this.deps.database().logger.warn('repairing queued messages at open was skipped', { + scope: 'journal-queued-message-repair', sessionId: this.deps.sessionId, - error: error instanceof Error ? error.message : String(error) + error }) }) } diff --git a/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.test.ts b/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.test.ts index 2f28adf0d545..61db09ad6d49 100644 --- a/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.test.ts +++ b/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.test.ts @@ -103,6 +103,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { const journal = await reopenAfterCrash() const settled = await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal, fence: 2, history: window([history('uuid-1', 'deploy the thing')]) @@ -118,6 +119,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { const journal = await reopenAfterCrash() const settled = await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal, fence: 2, history: window([]) @@ -144,6 +146,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { const journal = await reopenAfterCrash() const settled = await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal, fence: 2, history: window([], { turnInFlight: true }) @@ -157,6 +160,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { const journal = await reopenAfterCrash() const settled = await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal, fence: 2, history: window([], { boundaryConsistent: false }) @@ -180,6 +184,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { ) const settled = await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal, fence: 2, history: window([]) @@ -203,6 +208,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { ) const settled = await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal, fence: 2, history: window([history('uuid-1', 'first\nsecond')]) @@ -229,6 +235,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { await restarted.markPendingSubmissionsUnknown(2) await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal: restarted, fence: 2, history: window([history('uuid-old', 'deploy the thing')]) @@ -261,6 +268,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { await restarted.markPendingSubmissionsUnknown(2) await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal: restarted, fence: 2, history: window([history('uuid-old', 'deploy the thing')]) @@ -287,6 +295,7 @@ describe('reconcileJournalSubmissionsAgainstHistory', () => { await restarted.markPendingSubmissionsUnknown(2) await reconcileJournalSubmissionsAgainstHistory({ + sessionId: IDENTITY.sessionId, journal: restarted, fence: 2, history: window([history('uuid-1', 'ping'), history('uuid-2', 'ping')]) diff --git a/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.ts b/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.ts index f1484bf5da8a..dbfe4079d401 100644 --- a/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.ts +++ b/src/main/native-chat/agent-session-journal/journal-restart-reconciliation.ts @@ -86,6 +86,7 @@ function unseenHistory( * ids this pass settled, so the attach result stops reporting them unconfirmed. */ export async function reconcileJournalSubmissionsAgainstHistory(input: { + sessionId: string journal: AgentSessionJournal fence: number history: ProviderHistoryWindow @@ -101,7 +102,9 @@ export async function reconcileJournalSubmissionsAgainstHistory(input: { })) { if (outcome.outcome === 'unknown') { // Narrowing failed: the submission stays unconfirmed, so record why. - console.warn('[journal-reconcile] submission left unconfirmed:', { + input.journal.logger.warn('a submission was left unconfirmed', { + scope: 'journal-submission-reconcile', + sessionId: input.sessionId, clientMessageId: outcome.clientMessageId, reason: outcome.reason, fence: input.fence diff --git a/src/main/native-chat/agent-session-journal/journal-row-writer.ts b/src/main/native-chat/agent-session-journal/journal-row-writer.ts index a29585580ebe..ce1d7274dbd3 100644 --- a/src/main/native-chat/agent-session-journal/journal-row-writer.ts +++ b/src/main/native-chat/agent-session-journal/journal-row-writer.ts @@ -83,10 +83,11 @@ export class JournalRowWriter { this.deps.rolledBack?.() // The draft store re-derives what this missed from the committed rows: at open, and in // the drain step before a draft sends. - console.warn('[journal-append] row bookkeeping skipped:', { + this.deps.database().logger.warn('row bookkeeping was skipped', { + scope: 'journal-row-bookkeeping', sessionId: this.deps.sessionId, kind: row.kind, - error: error instanceof Error ? error.message : String(error) + error }) } } diff --git a/src/main/native-chat/agent-session-journal/journal-store.ts b/src/main/native-chat/agent-session-journal/journal-store.ts index 3de15cc3df60..95d053095c59 100644 --- a/src/main/native-chat/agent-session-journal/journal-store.ts +++ b/src/main/native-chat/agent-session-journal/journal-store.ts @@ -77,6 +77,8 @@ export { AgentSessionJournalError } from './journal-write-guards' export class AgentSessionJournal { private readonly identity: AgentSessionJournalIdentity private readonly database: JournalHostDatabase + /** The host's logger, for a step on this chat that carries on past a failure. */ + readonly logger: JournalHostDatabase['logger'] private readonly now: () => number private readonly mintEpoch: () => string @@ -99,6 +101,7 @@ export class AgentSessionJournal { constructor(options: AgentSessionJournalOptions) { this.identity = options.identity this.database = options.database + this.logger = options.database.logger this.now = options.now ?? (() => Date.now()) this.mintEpoch = options.mintEpoch ?? randomUUID this.state = createJournalReducerState(options.identity.sessionId, '') diff --git a/src/main/native-chat/agent-session-journal/queued-message-bookkeeping-failure.test.ts b/src/main/native-chat/agent-session-journal/queued-message-bookkeeping-failure.test.ts index 638a62bdf02a..59b220a2726d 100644 --- a/src/main/native-chat/agent-session-journal/queued-message-bookkeeping-failure.test.ts +++ b/src/main/native-chat/agent-session-journal/queued-message-bookkeeping-failure.test.ts @@ -93,7 +93,7 @@ describe('draft bookkeeping inside a journal append', () => { it('a throwing draft transition still commits the rejection row, and the next open recovers the draft', async () => { let journal = await open() await queueAndConsume(journal, 'draft-1') - const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const warn = vi.spyOn(journal.logger, 'warn') vi.spyOn(JournalQueuedMessages.prototype, 'onRowInTransaction').mockImplementationOnce(() => { throw new Error('table queued_messages has no column named returned_rejection') }) @@ -107,8 +107,8 @@ describe('draft bookkeeping inside a journal append', () => { expect(journal.submission('sub-draft-1')?.dispatchState).toBe('rejected') expect(journal.queuedMessages.get('draft-1')?.state).toBe('dispatched') expect(warn).toHaveBeenCalledWith( - '[journal-append] row bookkeeping skipped:', - expect.objectContaining({ kind: 'dispatch' }) + 'row bookkeeping was skipped', + expect.objectContaining({ scope: 'journal-row-bookkeeping', kind: 'dispatch' }) ) await journal.close() journal = await open() diff --git a/src/main/native-chat/agent-session-journal/queued-message-store.test.ts b/src/main/native-chat/agent-session-journal/queued-message-store.test.ts index c3910e466854..2f1b4d0b52da 100644 --- a/src/main/native-chat/agent-session-journal/queued-message-store.test.ts +++ b/src/main/native-chat/agent-session-journal/queued-message-store.test.ts @@ -24,7 +24,8 @@ import { import type { AgentSessionJournal } from './journal-store' import { closeTestJournalHostDatabases, - createTrackedJournalOpener + createTrackedJournalOpener, + openTestJournalHostDatabase } from './journal-host-database-test-support' const IDENTITY: AgentSessionJournalIdentity = { @@ -505,12 +506,16 @@ describe('open-time repair and retention', () => { const repair = vi .spyOn(JournalQueuedMessages.prototype, 'repairAndPrune') .mockRejectedValueOnce(new Error('SQLITE_FULL')) - const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const warn = vi.spyOn(openTestJournalHostDatabase(root).logger, 'warn') try { const journal = await open() expect(warn).toHaveBeenCalledWith( - '[journal-open] queued-message repair skipped:', - expect.objectContaining({ error: 'SQLITE_FULL' }) + 'repairing queued messages at open was skipped', + expect.objectContaining({ + scope: 'journal-queued-message-repair', + sessionId: IDENTITY.sessionId, + error: new Error('SQLITE_FULL') + }) ) await queueDraft(journal, 'draft-1') expect(journal.queuedMessages.list()).toHaveLength(1) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-at-rest-commands.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-at-rest-commands.test.ts index 140a99201156..a83557fa6b50 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-at-rest-commands.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-at-rest-commands.test.ts @@ -71,6 +71,7 @@ function adapter(catalog: ClaudeAtRestCommandCatalog): StructuredAgentSessionAda function catalogFor(workspacePath: string): ClaudeAtRestCommandCatalog { return new ClaudeAtRestCommandCatalog({ + logger: recordingStructuredAgentSessionLogger().logger, resolveWorkspacePath: async () => workspacePath, now: () => clock, // Only the folders this test writes, never the machine's own home. @@ -173,6 +174,7 @@ describe("a Claude chat whose Claude isn't running shows the `/` surface from it it('keeps a slow scan once it answers, never a staler one after a newer, and runs at most two', async () => { const pending: ((skills: string[]) => void)[] = [] const catalog = new ClaudeAtRestCommandCatalog({ + logger: recordingStructuredAgentSessionLogger().logger, resolveWorkspacePath: async () => workspace, now: () => clock, discover: () => @@ -231,7 +233,9 @@ describe("a Claude chat whose Claude isn't running shows the `/` surface from it it('waits out the window from when a scan lands, even one that failed', async () => { let calls = 0 let failNext = true + const logged = recordingStructuredAgentSessionLogger() const catalog = new ClaudeAtRestCommandCatalog({ + logger: logged.logger, resolveWorkspacePath: async () => workspace, now: () => clock, discover: async (args) => { @@ -247,25 +251,24 @@ describe("a Claude chat whose Claude isn't running shows the `/` surface from it } }) const record = store.getRecord(SESSION)! - const warned = vi.spyOn(console, 'warn').mockImplementation(() => undefined) - try { - catalog.read(record) - await vi.waitFor(() => expect(warned).toHaveBeenCalledOnce()) - catalog.read(record) - await new Promise((resolve) => setTimeout(resolve, 20)) - expect(calls).toBe(1) - clock += CLAUDE_AT_REST_COMMANDS_TTL_MS - catalog.read(record) - await vi.waitFor(() => - expect(namesOf(catalog.read(record) ?? null, 'skill')).toEqual(['review-pr']) - ) - clock += CLAUDE_AT_REST_COMMANDS_TTL_MS - 1 - catalog.read(record) - await new Promise((resolve) => setTimeout(resolve, 20)) - expect(calls).toBe(2) - } finally { - warned.mockRestore() - } + catalog.read(record) + await vi.waitFor(() => expect(logged.entries).toHaveLength(1)) + expect(logged.entries[0].fields).toMatchObject({ + scope: 'claude-at-rest-commands', + sessionId: SESSION + }) + catalog.read(record) + await new Promise((resolve) => setTimeout(resolve, 20)) + expect(calls).toBe(1) + clock += CLAUDE_AT_REST_COMMANDS_TTL_MS + catalog.read(record) + await vi.waitFor(() => + expect(namesOf(catalog.read(record) ?? null, 'skill')).toEqual(['review-pr']) + ) + clock += CLAUDE_AT_REST_COMMANDS_TTL_MS - 1 + catalog.read(record) + await new Promise((resolve) => setTimeout(resolve, 20)) + expect(calls).toBe(2) }) it('after a relaunch, with nothing remembered from before it', async () => { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-attach.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-attach.ts index 85f99056c3a7..9960812275e5 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-attach.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-attach.ts @@ -248,6 +248,7 @@ async function reconcileAgainstProviderHistory(input: { return [] } return reconcileJournalSubmissionsAgainstHistory({ + sessionId: input.identity.sessionId, journal: input.journal, fence: input.fence, history diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-chat-stop.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-chat-stop.ts index 77a6fa3434e0..8e0646e489ee 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-chat-stop.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-chat-stop.ts @@ -99,12 +99,6 @@ export function mutateWithChatStop( clientOperationId: envelope.clientOperationId, ...named, stopChild, - onStopChildError: (error) => - context.deps.logger.warn('ending the agent process on Stop failed', { - scope: 'stop-child', - sessionId, - error - }), // The host drops its child only once the exit is proven, and nothing else runs meanwhile. childReleased: () => context.sessions.get(sessionId)?.child !== child, endSession: (owed) => { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-compact-stop.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-compact-stop.test.ts index bbdc2b50b2fd..e720305bb02c 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-compact-stop.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-compact-stop.test.ts @@ -29,6 +29,9 @@ import { } from './structured-agent-session-host-test-data' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' import { createStructuredAgentSessionLogger } from './structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const CALLER = { callerKey: 'client-1' } @@ -47,6 +50,7 @@ beforeEach(async () => { // No echo of its own: each test writes the frames Claude would. claude = fakeClaude({ replayUuid: null }) adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-echo-working.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-echo-working.test.ts index 747319c3c66b..eb36fb5f0aa8 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-echo-working.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-echo-working.test.ts @@ -28,6 +28,9 @@ import { } from './structured-agent-session-host-test-data' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' import { createStructuredAgentSessionLogger } from './structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const CALLER = { callerKey: 'client-1' } @@ -43,6 +46,7 @@ beforeEach(async () => { claude.current = fakeClaude({ replayUuid: null }) const lifecycle: Promise[] = [] adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-queued-stop.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-queued-stop.test.ts index 5e4ac75b0662..a7344b561f81 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-queued-stop.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-queued-stop.test.ts @@ -30,6 +30,9 @@ import { resetHostTestOperationIds } from './structured-agent-session-host-test-data' import { createStructuredAgentSessionLogger } from './structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const CALLER = { callerKey: 'client-1' } // As Claude Code 2.1.280 advertises them on a turn's system/init frame. @@ -59,6 +62,7 @@ beforeEach(async () => { }) const lifecycle: Promise[] = [] adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-ends-session.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-ends-session.test.ts index ddef0ed0bb65..410c1458b38c 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-ends-session.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-ends-session.test.ts @@ -42,6 +42,8 @@ import { resetHostTestOperationIds } from './structured-agent-session-host-test-data' +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger + const CALLER = { callerKey: 'client-1' } // As Claude Code 2.1.280 advertises them on a turn's system/init frame. const CAPABILITIES = ['interrupt_receipt_v1', 'interrupt_cancel_queued_v1', 'msg_lifecycle_v1'] @@ -77,6 +79,7 @@ beforeEach(async () => { }) const lifecycle: Promise[] = [] adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-turn-end.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-turn-end.test.ts index 9e10a753f07e..b86e95dd42a7 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-turn-end.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-stop-turn-end.test.ts @@ -30,6 +30,9 @@ import { hostTestOperationId, resetHostTestOperationIds } from './structured-agent-session-host-test-data' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const CALLER = { callerKey: 'client-1' } // As Claude Code 2.1.280 advertises them on a turn's system/init frame. @@ -47,6 +50,7 @@ beforeEach(async () => { claude = fakeClaude({ replayUuid: null }) const lifecycle: Promise[] = [] adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-unproven-stop-send.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-unproven-stop-send.test.ts index b86e25674641..0533be3ef6c5 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-unproven-stop-send.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-unproven-stop-send.test.ts @@ -31,6 +31,8 @@ import { resetHostTestOperationIds } from './structured-agent-session-host-test-data' +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger + const CALLER = { callerKey: 'client-1' } const CAPABILITIES = ['interrupt_receipt_v1', 'interrupt_cancel_queued_v1', 'msg_lifecycle_v1'] @@ -51,6 +53,7 @@ beforeEach(async () => { }) const lifecycle: Promise[] = [] adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-owed-work-release.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-owed-work-release.test.ts index 8b2586a9ccba..ef45025f5ab0 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-owed-work-release.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-owed-work-release.test.ts @@ -33,6 +33,9 @@ import { } from './structured-agent-session-host-test-data' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' import { createStructuredAgentSessionLogger } from './structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const CALLER = { callerKey: 'client-1' } const SWEEP_MS = 5 @@ -59,6 +62,7 @@ beforeEach(async () => { landInit = resolve }) adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.test.ts index 2922c3fdb2ec..7c8470b04039 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.test.ts @@ -24,6 +24,9 @@ import { } from './structured-agent-session-host-test-data' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' import { createStructuredAgentSessionLogger } from './structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const CALLER = { callerKey: 'client-1' } const INIT_DELAY_MS = 40 @@ -52,6 +55,7 @@ beforeEach(async () => { } }) adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-registry.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-registry.ts index 3b675c4054a2..3f7bdd2a1e3b 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-registry.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-registry.ts @@ -6,8 +6,11 @@ // Tests install a host with a stub adapter and clear it on teardown. import type { StructuredAgentSessionHost } from './structured-agent-session-host' +import type { StructuredAgentSessionLogger } from './structured-agent-session-logger' let host: StructuredAgentSessionHost | null = null +// Kept past teardown, so a listener that throws when the last chat is released still reports. +let logger: StructuredAgentSessionLogger | null = null let held = false let stopWatchingHost: (() => void) | null = null const heldListeners = new Set<(held: boolean) => void>() @@ -29,11 +32,11 @@ function publishHeld(): void { try { listener(next) } catch (error) { - console.warn('[structured-agent-session] a held-chats listener threw', error) + logger?.warn('a held-chats listener threw', { scope: 'held-chats-listener', error }) } } } catch (error) { - console.warn('[structured-agent-session] reading whether chats are held failed', error) + logger?.warn('reading whether chats are held failed', { scope: 'held-chats-read', error }) } } @@ -41,11 +44,15 @@ export function setStructuredAgentSessionHost(next: StructuredAgentSessionHost | stopWatchingHost?.() stopWatchingHost = null host = next + // Why typeof: tests install partial hosts. + if (typeof next?.deps?.logger?.warn === 'function') { + logger = next.deps.logger + } try { stopWatchingHost = typeof next?.onSessionsHeld === 'function' ? next.onSessionsHeld(publishHeld) : null } catch (error) { - console.warn('[structured-agent-session] watching for held chats failed', error) + logger?.warn('watching for held chats failed', { scope: 'held-chats-watch', error }) } publishHeld() } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.test.ts new file mode 100644 index 000000000000..58f91b0ebc64 --- /dev/null +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.test.ts @@ -0,0 +1,80 @@ +import { describe, expect, it } from 'vitest' +import type { StructuredAgentSessionAdapter } from './structured-agent-session-adapter' +import { createStructuredAgentSessionRestartFailureLedger } from './structured-agent-session-restart-failure-ledger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' +import { STRUCTURED_AGENT_SESSION_RESUME_NOT_ELIGIBLE } from './structured-agent-session-restart-resume-runner' + +const PROMPT = 'private prompt the user typed' + +const adapter: StructuredAgentSessionAdapter = { + acquire: async () => { + throw new Error('not acquired in this test') + }, + dispatch: async () => { + throw new Error('not dispatched in this test') + }, + cancelTurn: async () => ({ cancelled: false }), + answerPrompt: async () => undefined, + setOption: async () => undefined +} + +describe('restart failure ledger settlement', () => { + it('names the operation and every affected session when a capsule write fails, and no error', async () => { + const log = recordingStructuredAgentSessionLogger() + // A capsule error can quote the recovery payload, which holds the user's prompt. + const fail = async (): Promise => { + throw new Error(`capsule write failed: ${PROMPT}`) + } + const ledger = createStructuredAgentSessionRestartFailureLedger({ + capsule: { + listFailed: async () => [], + completeResume: fail, + failResume: fail, + rollbackResume: fail, + dismiss: async () => 0, + clearAll: async () => 0 + }, + getRecord: () => null, + adapter, + retryable: () => false, + reveal: async () => undefined, + logger: log.logger, + now: () => 1_000, + enqueue: (operation) => operation() + }) + + await ledger.settle( + 'operation-1', + [ + { + sessionId: 'session-done', + outcome: 'refused', + reason: STRUCTURED_AGENT_SESSION_RESUME_NOT_ELIGIBLE + }, + { sessionId: 'session-a', outcome: 'refused', reason: 'agent_session_resume_refused' }, + { sessionId: 'session-b', outcome: 'refused', reason: 'agent_session_resume_refused' } + ], + { + candidates: [], + markers: new Map(), + failureAfterResume: () => null, + failureReason: () => 'unused' + } + ) + + expect(log.entries.map(({ fields }) => fields)).toEqual([ + { scope: 'restart-offer-complete', operationId: 'operation-1', sessionIds: ['session-done'] }, + { + scope: 'restart-failure-record', + operationId: 'operation-1', + sessionIds: ['session-a', 'session-b'] + }, + { + scope: 'restart-offer-rollback', + operationId: 'operation-1', + sessionIds: ['session-done', 'session-a', 'session-b'] + } + ]) + expect(JSON.stringify(log.entries)).not.toContain(PROMPT) + }) +}) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.ts index 63722d1737cc..800af9ddb681 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-failure-ledger.ts @@ -182,7 +182,8 @@ export function createStructuredAgentSessionRestartFailureLedger(deps: { .catch(() => { deps.logger.warn('completing a restart offer failed', { scope: 'restart-offer-complete', - operationId + operationId, + sessionIds: completed }) }) // Filed before the rollback so a failure the user must act on is never reopened as an offer @@ -192,7 +193,8 @@ export function createStructuredAgentSessionRestartFailureLedger(deps: { .catch(() => { deps.logger.warn('recording a restart failure failed', { scope: 'restart-failure-record', - operationId + operationId, + sessionIds: failures.map((failure) => failure.sessionId) }) }) // This only reopens rows still owned by this operation. Rows removed by completeResume stay @@ -202,7 +204,9 @@ export function createStructuredAgentSessionRestartFailureLedger(deps: { .catch(() => { deps.logger.warn('rolling back a restart offer failed', { scope: 'restart-offer-rollback', - operationId + operationId, + // Every session the operation settled: which rows it still owned depends on the writes above. + sessionIds: outcomes.map((outcome) => outcome.sessionId) }) }) } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-turns-cancel.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-turns-cancel.ts index 48500afa12f3..d970bf40bf91 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-turns-cancel.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-turns-cancel.ts @@ -111,8 +111,6 @@ export async function performCancel( /** Ends the provider child, for a running command the provider did not take the Stop on, or a * turn whose interrupt failed. */ stopChild?: () => Promise - /** A child end after a failed interrupt that threw. */ - onStopChildError?: (error: unknown) => void /** After that throw: whether the host let go of the child, its exit proven before a later * cleanup step failed. */ childReleased?: () => boolean @@ -242,7 +240,11 @@ export async function performCancel( await input.stopChild() ended = true } catch (error) { - input.onStopChildError?.(error) + ctx.logger.warn('ending the agent process on Stop failed', { + scope: 'stop-child', + sessionId: ctx.sessionId, + error + }) // Unless the exit was proven, the child may still run the turn and the failed row stays true. ended = input.childReleased?.() === true } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-view-start-after-failed-start.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-view-start-after-failed-start.test.ts index 20c5abd595e8..221ce58b7ecc 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-view-start-after-failed-start.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-view-start-after-failed-start.test.ts @@ -26,6 +26,9 @@ import { } from './structured-agent-session-host-test-data' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' import { createStructuredAgentSessionLogger } from './structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from './structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger /** Delivery runs on its own serialized steps; under a loaded runner they take more than a second. */ function eventually(assertion: () => unknown): Promise { @@ -54,6 +57,7 @@ beforeEach(async () => { // Every start spawns, is published, and exits before it answers initialize. claude = fakeClaude({ initDelayMs: 20, exitBeforeInit: LAUNCH_FAILURE }) adapter = new ClaudeStructuredSessionAdapter({ + logger: TEST_LOGGER, resolveLaunch: async () => ({ pathToClaudeCodeExecutable: 'claude', options: {}, diff --git a/src/main/native-chat/agent-session-wire/structured-chat-logger-ratchet.test.ts b/src/main/native-chat/agent-session-wire/structured-chat-logger-ratchet.test.ts new file mode 100644 index 000000000000..dcb48cb73a0b --- /dev/null +++ b/src/main/native-chat/agent-session-wire/structured-chat-logger-ratchet.test.ts @@ -0,0 +1,164 @@ +import { join, resolve } from 'node:path' +import { describe, expect, it } from 'vitest' +import { scanSourceTree, stripComments } from '../../../shared/source-scan/source-tree-scan' + +/** + * Structured chat reports a failure it carries on past through the host's logger, and nowhere else. + * + * A packaged desktop main process has no console, so a `console.warn` there reaches nobody. An + * optional `on*Error?` callback compiles fine when a caller forgets it, and the failure is dropped. + * Both shapes are how failures went missing before the logger was required. + */ + +// Paths are '/'-separated on every platform (scanSourceTree normalizes them). +const SCOPE_PREFIXES = [ + 'main/native-chat/agent-session-wire/', + 'main/native-chat/agent-session-journal/', + 'main/native-chat/structured-agent-session-', + 'main/claude/claude-structured-', + 'main/codex/codex-structured-', + 'main/runtime/structured-', + 'main/runtime/orchestration/structured-', + // No trailing dash: the agentSession RPC file itself is `structured-agent-session.ts`. + 'main/runtime/rpc/methods/structured-agent-session', + 'main/runtime/rpc/methods/structured-session-', + 'main/runtime/rpc/methods/orchestration-structured-', + 'main/runtime/rpc/methods/orchestration/worker/structured-worker-' +] + +/** Structured chat code whose name does not say so. */ +const SCOPE_FILES = new Set([ + // Opened and built only by structured Claude chats. + 'main/claude/claude-stream-json-connection.ts', + 'main/claude/claude-at-rest-commands.ts', + // Install the structured host before a structured worker's stop or release. + 'main/runtime/rpc/methods/orchestration/worker/worker-stop.ts', + 'main/runtime/rpc/methods/orchestration/worker/worker-release-completion.ts' +]) + +/** The logger's own sink. */ +const CONSOLE_ALLOWED = new Set([ + 'main/native-chat/agent-session-wire/structured-agent-session-logger.ts' +]) + +const WIRE = 'main/native-chat/agent-session-wire/' + +/** Optional hooks that change what happens, not whether a failure is reported, by file. */ +const BEHAVIORAL_OPTIONAL_HOOKS: ReadonlyMap> = new Map([ + // Hands the refusal to the attach caller that answers the client. + [`${WIRE}structured-agent-session-attach-flow.ts`, new Set(['onAcquisitionFailed'])], + [`${WIRE}structured-agent-session-attach-orchestration.ts`, new Set(['onAcquisitionFailed'])], + // Ends the Claude session whose background-task journal writes failed. + [ + 'main/claude/claude-structured-journal-translation.ts', + new Set(['onBackgroundTaskJournalFailure']) + ], + // Stops the provider whose own journal sink failed; the sink reports the failure itself. + [`${WIRE}structured-agent-session-event-sink.ts`, new Set(['onFailed'])], + [`${WIRE}structured-agent-session-event-sink-queue.ts`, new Set(['onFailed'])], + [`${WIRE}structured-agent-session-host-runtime-state.ts`, new Set(['onEventSinkFailure'])] +]) + +const CONSOLE_PATTERNS = [ + /\bconsole\s*(?:\?\.|\.)\s*(?:warn|error)\b/g, + /\bconsole\s*(?:\?\.)?\s*\[\s*['"`](?:warn|error)['"`]\s*\]/g, + /\{[^}]*\b(?:warn|error)\b[^}]*\}\s*=\s*console\b/g +] + +const OPTIONAL_FAILURE_CALLBACK = + /\b(on(?:[A-Z]\w*)?(?:Error|Errors|Failed|Failure|Failures))\s*\?\s*:/g + +function lineOf(code: string, index: number): number { + return code.slice(0, index).split('\n').length +} + +/** `line: what` for each console failure write and each reporting-only optional failure hook. */ +export function findStructuredChatLoggerBypasses( + source: string, + options: { consoleAllowed?: boolean; behavioralHooks?: ReadonlySet } = {} +): string[] { + const code = stripComments(source) + const found: string[] = [] + if (!options.consoleAllowed) { + for (const pattern of CONSOLE_PATTERNS) { + for (const match of code.matchAll(pattern)) { + found.push(`${lineOf(code, match.index)}: ${match[0]}`) + } + } + } + for (const match of code.matchAll(OPTIONAL_FAILURE_CALLBACK)) { + if (!options.behavioralHooks?.has(match[1])) { + found.push(`${lineOf(code, match.index)}: ${match[1]}?`) + } + } + return found +} + +function inScope(relativePath: string): boolean { + return ( + (SCOPE_FILES.has(relativePath) || + SCOPE_PREFIXES.some((prefix) => relativePath.startsWith(prefix))) && + !relativePath.includes('-test-support') + ) +} + +describe('structured chat logger ratchet', () => { + it('flags console failure writes in every spelling', () => { + const flagged = [ + `console.warn('x', error)`, + `console.error('x')`, + `console?.warn('x')`, + `console['warn']('x')`, + `const { warn } = console` + ] + for (const source of flagged) { + expect(findStructuredChatLoggerBypasses(source), source).toHaveLength(1) + } + }) + + it('flags an optional failure callback, and leaves required and behavioral ones alone', () => { + expect(findStructuredChatLoggerBypasses('type D = { onError?: (e: unknown) => void }')).toEqual( + ['1: onError?'] + ) + expect( + findStructuredChatLoggerBypasses('type D = { onSinkFailed ?: () => void }') + ).toHaveLength(1) + expect(findStructuredChatLoggerBypasses('type D = { onFailure?: () => void }')).toHaveLength(1) + expect(findStructuredChatLoggerBypasses('type D = { onFailed: () => void }')).toEqual([]) + expect( + findStructuredChatLoggerBypasses('type D = { onAcquisitionFailed?: () => void }', { + behavioralHooks: new Set(['onAcquisitionFailed']) + }) + ).toEqual([]) + }) + + it('leaves prose, console.log and the logger itself alone', () => { + expect(findStructuredChatLoggerBypasses('// console.warn used to drop this')).toEqual([]) + expect(findStructuredChatLoggerBypasses(`console.log('x')`)).toEqual([]) + expect(findStructuredChatLoggerBypasses(`console.warn('x')`, { consoleAllowed: true })).toEqual( + [] + ) + }) + + const repoRoot = resolve(__dirname, '..', '..', '..', '..') + const files = scanSourceTree(join(repoRoot, 'src')).filter(({ relativePath }) => + inScope(relativePath) + ) + + it('scans a plausible number of files', () => { + // A broken root or prefix list would make the guard silently vacuous. + expect(files.length).toBeGreaterThan(300) + const scanned = new Set(files.map(({ relativePath }) => relativePath)) + expect([...SCOPE_FILES].filter((path) => !scanned.has(path))).toEqual([]) + }) + + it('has no structured chat failure that bypasses the logger', () => { + const offenders = files.flatMap(({ relativePath, source }) => + findStructuredChatLoggerBypasses(source, { + consoleAllowed: CONSOLE_ALLOWED.has(relativePath), + behavioralHooks: BEHAVIORAL_OPTIONAL_HOOKS.get(relativePath) + }).map((hit) => `src/${relativePath}:${hit}`) + ) + expect(offenders).toEqual([]) + }) +}) diff --git a/src/main/native-chat/wsl-transcript-fs-gate.test.ts b/src/main/native-chat/wsl-transcript-fs-gate.test.ts index b886168949a2..2bf909b5ecfa 100644 --- a/src/main/native-chat/wsl-transcript-fs-gate.test.ts +++ b/src/main/native-chat/wsl-transcript-fs-gate.test.ts @@ -9,6 +9,7 @@ import { WSL_TRANSCRIPT_FS_SCAN_TIMEOUT_MS, WslTranscriptFsError } from './wsl-transcript-fs-gate' +import { _resetTracerForTests, setActiveSink } from '../observability/tracer' const SLOW_MESSAGE = 'WSL transcript files are temporarily unavailable because filesystem access is taking too long. Try again shortly or restart Orca if the issue continues.' @@ -764,6 +765,34 @@ describe('WSL transcript filesystem task scheduling', () => { } }) + it('writes a task that outlives its deadline to the trace, not only the console', async () => { + vi.useFakeTimers() + const records: unknown[] = [] + setActiveSink({ push: (record) => records.push(record), flush: () => {}, close: () => {} }) + const stalled = deferred() + try { + const stuck = run('\\\\wsl.localhost\\Ubuntu\\traced', 'exact', () => stalled.promise) + const stuckRejected = expect(stuck).rejects.toMatchObject({ code: 'timeout' }) + await vi.advanceTimersByTimeAsync(WSL_TRANSCRIPT_FS_EXACT_TIMEOUT_MS) + await stuckRejected + expect(records).toEqual([ + expect.objectContaining({ + name: 'wslTranscriptFs.timeout', + attributes: expect.objectContaining({ + priority: 'exact', + timeoutMs: WSL_TRANSCRIPT_FS_EXACT_TIMEOUT_MS + }), + exit: expect.objectContaining({ _tag: 'Failure' }) + }) + ]) + } finally { + stalled.resolve('late') + await vi.advanceTimersByTimeAsync(0) + vi.useRealTimers() + _resetTracerForTests() + } + }) + it('does not mark a scan permit stuck before the scan deadline', async () => { vi.useFakeTimers() const exactWork = deferred() diff --git a/src/main/native-chat/wsl-transcript-fs-gate.ts b/src/main/native-chat/wsl-transcript-fs-gate.ts index d4413c91323f..66db0634c04a 100644 --- a/src/main/native-chat/wsl-transcript-fs-gate.ts +++ b/src/main/native-chat/wsl-transcript-fs-gate.ts @@ -1,4 +1,5 @@ import { wslTranscriptFsLaneKey, wslTranscriptFsRouteKey } from './wsl-transcript-fs-route' +import { reportWslTranscriptFsTimeout } from './wsl-transcript-fs-timeout-report' import { WslTranscriptFsError, wslTranscriptFsCapacityError as capacityError, @@ -257,10 +258,7 @@ function pumpTasks(): void { activeTasks.add(task) task.deadlineTimer = setTimeout(() => { const error = timeoutError() - console.warn( - `[wsl-transcript-fs-gate] ${task.priority} filesystem task exceeded ` + - `${timeoutMs(task.priority)}ms; replacing its I/O process: ${task.key}` - ) + reportWslTranscriptFsTimeout(task, timeoutMs(task.priority), error) // Keep polling from churning replacement processes on the same stalled mount. quarantineRoute(task.route, timeoutMs(task.priority), task.startedAt ?? performance.now()) failQueuedRouteTasks(task.route) diff --git a/src/main/native-chat/wsl-transcript-fs-timeout-report.ts b/src/main/native-chat/wsl-transcript-fs-timeout-report.ts new file mode 100644 index 000000000000..550de214d181 --- /dev/null +++ b/src/main/native-chat/wsl-transcript-fs-timeout-report.ts @@ -0,0 +1,17 @@ +import { startSpan } from '../observability/tracer' + +/** A filesystem task that outlived its deadline. The trace keeps it in a packaged app; scanner + * workers install no trace sink, so the console line stays. */ +export function reportWslTranscriptFsTimeout( + task: { priority: string; key: string }, + timeoutMs: number, + error: Error +): void { + startSpan('wslTranscriptFs.timeout', { + attributes: { priority: task.priority, timeoutMs, taskKey: task.key } + }).fail(error) + console.warn( + `[wsl-transcript-fs-gate] ${task.priority} filesystem task exceeded ` + + `${timeoutMs}ms; replacing its I/O process: ${task.key}` + ) +} diff --git a/src/main/runtime/claude-structured-fake-connection-test-fixture.ts b/src/main/runtime/claude-structured-fake-connection-test-fixture.ts index 3404bcbf283c..5a1e0f60373c 100644 --- a/src/main/runtime/claude-structured-fake-connection-test-fixture.ts +++ b/src/main/runtime/claude-structured-fake-connection-test-fixture.ts @@ -24,7 +24,7 @@ export function fakeClaude(providerSession: string) { null let contextUsage: () => Promise = async () => ({}) // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: the fake answers every control request the session issues; the real opener's signature is what the runtime under test calls. - const openConnection = (async (launch, handlers = {}) => { + const openConnection = (async (launch, handlers) => { const connection: FakeClaudeConnection = { launch, handlers, diff --git a/src/main/runtime/orca-runtime-get-pty-record-for-pane-key.ts b/src/main/runtime/orca-runtime-get-pty-record-for-pane-key.ts index 5906ee91866c..37c4cdead788 100644 --- a/src/main/runtime/orca-runtime-get-pty-record-for-pane-key.ts +++ b/src/main/runtime/orca-runtime-get-pty-record-for-pane-key.ts @@ -11,7 +11,7 @@ import { handleLessCoordinatorSessionId, structuredSessionAddressTarget, structuredSessionMailTarget, - structuredSessionIdleEdgeMailboxes, + redriveStructuredSessionMail, structuredWorkerMailSessionId } from './orchestration/structured-session-mail-target' import { @@ -206,18 +206,12 @@ export class OrcaRuntimeWithGetPtyRecordForPaneKey extends OrcaRuntimeWithPruneM if (summary.status === 'working' || summary.status === 'attention') { return } - // Logged, never thrown: the same status callback goes on to the first-turn workspace rename. - try { - this.notifyStructuredSessionJournalActivity(summary.sessionId) - const openDb = () => this.getExistingOrchestrationDb() - const deliver = (mailbox: string) => this.deliverPendingMessagesForHandle(mailbox) - structuredSessionIdleEdgeMailboxes(summary.sessionId, openDb).forEach(deliver) - } catch (error) { - console.warn('[orchestration] structured session mail redrive failed', { - sessionId: summary.sessionId, - error: error instanceof Error ? error.message : String(error) - }) - } + redriveStructuredSessionMail(summary.sessionId, { + notifyJournalActivity: (sessionId) => this.notifyStructuredSessionJournalActivity(sessionId), + openDb: () => this.getExistingOrchestrationDb(), + deliver: (mailbox) => this.deliverPendingMessagesForHandle(mailbox), + logger: this.structuredAgentSessionLogger + }) } /** Settlement drops anything parked for the session; nothing will ever redrive it again. */ diff --git a/src/main/runtime/orca-runtime-get-worktree-ps.ts b/src/main/runtime/orca-runtime-get-worktree-ps.ts index b25ce381def3..2de295bc7d76 100644 --- a/src/main/runtime/orca-runtime-get-worktree-ps.ts +++ b/src/main/runtime/orca-runtime-get-worktree-ps.ts @@ -14,7 +14,6 @@ import { compareWorktreePs } from './runtime-worktree-status-projection' import type { Repo } from '../../shared/repo-types' import { enrichMissingRepoGitRemoteIdentities } from '../repo-git-remote-identity-enrichment' import { ensureStructuredAgentSessionHost as installStructuredAgentSessionHost } from './structured-agent-session-runtime' -import { createStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' import { maybeAutoRenameWorkspaceOnFirstStructuredTurn } from '../agent-hooks/first-work-structured-session-rename' import { firstWorkRenameDeps } from '../agent-hooks/first-work-rename-runtime' import { getProfileUserDataPath } from '../orca-profiles/profile-storage-paths' @@ -144,7 +143,7 @@ export class OrcaRuntimeWithGetWorktreePs extends OrcaRuntimeWithStartTuiIdleVis hostId: LOCAL_EXECUTION_HOST_ID, claimKeyId: this.agentSessionClaimSigner.keyId, // The host's local trace file (the desktop's or orcad's own), plus the console. - logger: createStructuredAgentSessionLogger(), + logger: this.structuredAgentSessionLogger, // Resolves folder workspaces as well as git worktrees, so a chat session // in a plain folder lands in the folder rather than failing to resolve. resolveWorkspacePath: async (workspaceId) => diff --git a/src/main/runtime/orca-runtime-preserved-branch-cleanup.ts b/src/main/runtime/orca-runtime-preserved-branch-cleanup.ts index 37f8121f99ae..7ae32c426ba8 100644 --- a/src/main/runtime/orca-runtime-preserved-branch-cleanup.ts +++ b/src/main/runtime/orca-runtime-preserved-branch-cleanup.ts @@ -11,6 +11,7 @@ import type { import type { TerminalSideEffectBatch } from '../../shared/terminal-side-effect-facts' import type { AgentStatusIpcPayload } from '../../shared/agent-status-types' import type { StructuredAgentSessionStatusSink } from '../native-chat/agent-session-wire/structured-agent-session-status-feed' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' import type { ObservedAgentStatusPaneIdentity } from '../ipc/agent-status-ipc-boundary' import type { AgentHookAuthorityAttestation } from '../agent-hooks/server' import type { RuntimeDesktopWindowStatus } from '../../shared/runtime-types' @@ -69,6 +70,9 @@ export class OrcaRuntimeWithPreservedBranchCleanup extends OrcaRuntimeWithTermin protected readonly structuredAgentStatusSinkFn: StructuredAgentSessionStatusSink | null + /** The structured chat host's logger, held here so callers outside the host report to it too. */ + readonly structuredAgentSessionLogger: StructuredAgentSessionLogger + protected readonly readObservedAgentStatusPaneIdentityFn: ( paneKey: string ) => ObservedAgentStatusPaneIdentity diff --git a/src/main/runtime/orca-runtime-state-fields.ts b/src/main/runtime/orca-runtime-state-fields.ts index ede9c6edce59..15d981f98c81 100644 --- a/src/main/runtime/orca-runtime-state-fields.ts +++ b/src/main/runtime/orca-runtime-state-fields.ts @@ -8,6 +8,11 @@ import type { RuntimeTerminalAgentStatusEvent } from './runtime-terminal-contrac import type { TerminalSideEffectBatch } from '../../shared/terminal-side-effect-facts' import type { AgentStatusIpcPayload } from '../../shared/agent-status-types' import type { StructuredAgentSessionStatusSink } from '../native-chat/agent-session-wire/structured-agent-session-status-feed' +import { + createStructuredAgentSessionLogger, + neverThrowingStructuredAgentSessionLogger, + type StructuredAgentSessionLogger +} from '../native-chat/agent-session-wire/structured-agent-session-logger' import type { ObservedAgentStatusPaneIdentity } from '../ipc/agent-status-ipc-boundary' import type { AgentHookAuthorityAttestation } from '../agent-hooks/server' import type { @@ -66,6 +71,7 @@ export class OrcaRuntimeWithStateFields extends OrcaRuntimeWithLinearCommands { /** Where structured (native chat) sessions publish into that same store, so the snapshot * above lists them like every other agent. */ structuredAgentStatusSink?: StructuredAgentSessionStatusSink + structuredAgentSessionLogger?: StructuredAgentSessionLogger /** The identity the runtime resolved for a pane as each status arrived. Without it the * fleet path reminted cached rows against whatever the pane owns now. */ readObservedAgentStatusPaneIdentity?: (paneKey: string) => ObservedAgentStatusPaneIdentity @@ -219,6 +225,9 @@ export class OrcaRuntimeWithStateFields extends OrcaRuntimeWithLinearCommands { } this.getAgentStatusSnapshotFn = deps?.getAgentStatusSnapshot ?? null this.structuredAgentStatusSinkFn = deps?.structuredAgentStatusSink ?? null + this.structuredAgentSessionLogger = neverThrowingStructuredAgentSessionLogger( + deps?.structuredAgentSessionLogger ?? createStructuredAgentSessionLogger() + ) this.readObservedAgentStatusPaneIdentityFn = deps?.readObservedAgentStatusPaneIdentity ?? (() => ({ kind: 'unobserved' })) this.getAgentProviderSessionSnapshotFn = diff --git a/src/main/runtime/orchestration/structured-mailbox-pointer-host.ts b/src/main/runtime/orchestration/structured-mailbox-pointer-host.ts index ecfdff0dff5f..7fa5cefb8588 100644 --- a/src/main/runtime/orchestration/structured-mailbox-pointer-host.ts +++ b/src/main/runtime/orchestration/structured-mailbox-pointer-host.ts @@ -70,7 +70,11 @@ async function readSessionJournal(sessionId: string): Promise = {}): MailTargetProbe { return Object.assign(Object.create(MailTargetProbe.prototype), { _orchestrationDb: db, ptysById: new Map(), + structuredAgentSessionLogger: recordingStructuredAgentSessionLogger().logger, ...extra }) as MailTargetProbe } @@ -244,8 +246,12 @@ describe('the idle edge after a restart, before any orchestration call', () => { }) /** A runtime whose database has not been opened in this process yet. */ - function restarted(delivered: string[]): MailTargetProbe { + function restarted( + delivered: string[], + logger = recordingStructuredAgentSessionLogger().logger + ): MailTargetProbe { return probe({ + structuredAgentSessionLogger: logger, _orchestrationDb: null, ensureOrchestrationFederationRelay: vi.fn(), scheduleRestoredMessageRepoints: vi.fn(), @@ -277,22 +283,25 @@ describe('the idle edge after a restart, before any orchestration call', () => { it('creates no database for a profile that never orchestrated, and says nothing', () => { installStore(chatRecord()) - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const log = recordingStructuredAgentSessionLogger() const delivered: string[] = [] - restarted(delivered).onStructuredSessionStatusForMail({ sessionId: CHAT, status: 'idle' }) + restarted(delivered, log.logger).onStructuredSessionStatusForMail({ + sessionId: CHAT, + status: 'idle' + }) expect(delivered).toEqual([]) expect(existsSync(join(userData, 'orchestration.db'))).toBe(false) - expect(warn).not.toHaveBeenCalled() - warn.mockRestore() + expect(log.entries).toEqual([]) }) it('says so when the database cannot be opened, instead of skipping silently', () => { installStore(chatRecord()) - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const log = recordingStructuredAgentSessionLogger() const deliver = vi.fn() probe({ + structuredAgentSessionLogger: log.logger, _orchestrationDb: null, getExistingOrchestrationDb: () => { throw new Error('userData unavailable') @@ -301,11 +310,9 @@ describe('the idle edge after a restart, before any orchestration call', () => { notifyStructuredSessionJournalActivity: vi.fn() }).onStructuredSessionStatusForMail({ sessionId: CHAT, status: 'idle' }) expect(deliver).not.toHaveBeenCalled() - expect(warn).toHaveBeenCalledWith( - '[orchestration] skipped a structured session mail edge: no database', - { sessionId: CHAT, error: 'userData unavailable' } - ) - warn.mockRestore() + expect(log.entries.map(({ fields }) => fields)).toEqual([ + { scope: 'mail-edge-database', sessionId: CHAT, error: new Error('userData unavailable') } + ]) }) }) diff --git a/src/main/runtime/orchestration/structured-session-mail-target.ts b/src/main/runtime/orchestration/structured-session-mail-target.ts index 73bec03c1a56..04f7f14475eb 100644 --- a/src/main/runtime/orchestration/structured-session-mail-target.ts +++ b/src/main/runtime/orchestration/structured-session-mail-target.ts @@ -25,6 +25,7 @@ import { type AgentSessionRecordReader } from './structured-session-lineage' import type { RunRow } from './types' +import type { StructuredAgentSessionLogger } from '../../native-chat/agent-session-wire/structured-agent-session-logger' /** * The session a Run's coordinator binding names when that binding has no handle. A structured @@ -112,17 +113,42 @@ export function structuredSessionOwnedMailboxes(sessionId: string, db: Orchestra * no mail, so `openDb` answers null and nothing is created. */ export function structuredSessionIdleEdgeMailboxes( sessionId: string, - openDb: () => OrchestrationDb | null + openDb: () => OrchestrationDb | null, + logger: StructuredAgentSessionLogger ): string[] { let db: OrchestrationDb | null try { db = openDb() } catch (error) { - console.warn('[orchestration] skipped a structured session mail edge: no database', { + logger.warn('a structured session mail edge was skipped: no database', { + scope: 'mail-edge-database', sessionId, - error: error instanceof Error ? error.message : String(error) + error }) return [] } return db ? structuredSessionOwnedMailboxes(sessionId, db) : [] } + +/** A session's idle edge: retry what is parked on it and point the mail it owns again. Logged, + * never thrown: the same status callback goes on to the first-turn workspace rename. */ +export function redriveStructuredSessionMail( + sessionId: string, + deps: { + notifyJournalActivity: (sessionId: string) => void + openDb: () => OrchestrationDb | null + deliver: (mailbox: string) => void + logger: StructuredAgentSessionLogger + } +): void { + try { + deps.notifyJournalActivity(sessionId) + structuredSessionIdleEdgeMailboxes(sessionId, deps.openDb, deps.logger).forEach(deps.deliver) + } catch (error) { + deps.logger.warn('a structured session mail redrive failed', { + scope: 'mail-redrive', + sessionId, + error + }) + } +} diff --git a/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.test.ts b/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.test.ts index b669233c31fb..c58a252f2d9c 100644 --- a/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.test.ts +++ b/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.test.ts @@ -1,6 +1,9 @@ import { beforeEach, describe, expect, it, vi } from 'vitest' import type { AgentJournalRenderItem } from '../../../../shared/agent-session-journal-types' import type { StructuredWorkerIdentity } from '../../structured-worker-identity' +import { recordingStructuredAgentSessionLogger } from '../../../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const hostRef: { current: unknown } = { current: null } @@ -149,7 +152,8 @@ describe('structured worker stop', () => { const retireStructuredAgentSessionTabFromSnapshot = vi.fn() const result = await stopStructuredWorker(IDENTITY, 'd1', { forgetStructuredSessionMail: vi.fn(), - retireStructuredAgentSessionTabFromSnapshot + retireStructuredAgentSessionTabFromSnapshot, + structuredAgentSessionLogger: TEST_LOGGER }) expect(result).toMatchObject({ stopped: false, closeAttempted: true }) expect(retireStructuredAgentSessionTabFromSnapshot).not.toHaveBeenCalled() diff --git a/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.ts b/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.ts index bec15537c49d..c175c86c6ba9 100644 --- a/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.ts +++ b/src/main/runtime/rpc/methods/orchestration-structured-worker-lifecycle.ts @@ -78,7 +78,9 @@ export async function stopStructuredWorker( dispatchId: string, runtime?: Pick< OrcaRuntimeService, - 'forgetStructuredSessionMail' | 'retireStructuredAgentSessionTabFromSnapshot' + | 'forgetStructuredSessionMail' + | 'retireStructuredAgentSessionTabFromSnapshot' + | 'structuredAgentSessionLogger' > ): Promise { return closeStructuredAgentSessionChild(identity.sessionId, { diff --git a/src/main/runtime/rpc/methods/orchestration-structured-worker-session.test.ts b/src/main/runtime/rpc/methods/orchestration-structured-worker-session.test.ts index c3c69dc15fd2..0f5081156a56 100644 --- a/src/main/runtime/rpc/methods/orchestration-structured-worker-session.test.ts +++ b/src/main/runtime/rpc/methods/orchestration-structured-worker-session.test.ts @@ -3,6 +3,9 @@ import { beforeEach, describe, expect, it, vi } from 'vitest' import type { AgentJournalSubmission } from '../../../../shared/agent-session-journal-types' import { getAppEnvironment } from '../../../../shared/app-environment' import { DISPATCH_REJECTED_WRITE_FAILED } from '../../../../shared/structured-agent-session-dispatch-rejection' +import { recordingStructuredAgentSessionLogger } from '../../../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const hostRef: { current: unknown } = { current: null } const createSpy = vi.fn() @@ -84,7 +87,7 @@ describe('structured worker session', () => { createSpy.mockImplementation(async (args: { envelope: { sessionId: string } }) => { // `attach` is what spawns the provider child, and the child's env is read from the registry // at spawn time. Registering afterwards ships a worker with no ORCA_TERMINAL_HANDLE. - envAtSpawn = structuredSessionChildIdentityEnv(args.envelope.sessionId, {}) + envAtSpawn = structuredSessionChildIdentityEnv(args.envelope.sessionId, {}, TEST_LOGGER) return { ok: true, value: { sessionId: args.envelope.sessionId } } }) const created = await createStructuredWorkerSession({ diff --git a/src/main/runtime/rpc/methods/orchestration-structured-worker-session.ts b/src/main/runtime/rpc/methods/orchestration-structured-worker-session.ts index a5a79b6be153..8896dd64a4b6 100644 --- a/src/main/runtime/rpc/methods/orchestration-structured-worker-session.ts +++ b/src/main/runtime/rpc/methods/orchestration-structured-worker-session.ts @@ -180,7 +180,10 @@ function structuredCreateMayHaveCommitted( */ export async function discardStructuredWorkerSession( sessionId: string, - runtime: Pick + runtime: Pick< + OrcaRuntimeService, + 'retireStructuredAgentSessionTabFromSnapshot' | 'structuredAgentSessionLogger' + > ): Promise { const host = getStructuredAgentSessionHost() if (!host) { @@ -190,11 +193,11 @@ export async function discardStructuredWorkerSession( await host.setSessionTabVisibility?.(sessionId, false) await host.close(sessionId, 'evict') } catch (error) { - console.warn( - '[orchestration] failed to discard a half-started structured worker', + host.deps.logger.warn('discarding a half-started structured worker failed', { + scope: 'worker-discard', sessionId, error - ) + }) return } retireSettledStructuredWorkerTab(sessionId, runtime) @@ -346,7 +349,11 @@ async function subscribeForRedrive( unsubscribe() } } catch (error) { - console.warn('[orchestration] structured worker redrive subscription failed', sessionId, error) + host.deps.logger.warn('subscribing a structured worker for mail redrive failed', { + scope: 'worker-redrive-subscribe', + sessionId, + error + }) coalescer.dispose() return () => {} } diff --git a/src/main/runtime/rpc/methods/orchestration/worker/worker-release-completion.ts b/src/main/runtime/rpc/methods/orchestration/worker/worker-release-completion.ts index 4aca4d0420a0..37e2ae2d90c2 100644 --- a/src/main/runtime/rpc/methods/orchestration/worker/worker-release-completion.ts +++ b/src/main/runtime/rpc/methods/orchestration/worker/worker-release-completion.ts @@ -101,10 +101,9 @@ async function completeWorkerTerminalReleaseOnce( // worker's redrive subscription. Until that exists, a worker that survives a restart has its // parked mail wait for the next arrival rather than a settle edge. await runtime.ensureStructuredAgentSessionHost().catch((error: unknown) => { - console.warn( - '[orchestration] structured host install failed before release', - dispatchId, - error + runtime.structuredAgentSessionLogger.warn( + 'installing the structured host before a worker release failed', + { scope: 'worker-release-host-install', dispatchId, error } ) }) } diff --git a/src/main/runtime/rpc/methods/orchestration/worker/worker-stop.ts b/src/main/runtime/rpc/methods/orchestration/worker/worker-stop.ts index ee0e73c904f8..1d40131987ab 100644 --- a/src/main/runtime/rpc/methods/orchestration/worker/worker-stop.ts +++ b/src/main/runtime/rpc/methods/orchestration/worker/worker-stop.ts @@ -133,10 +133,9 @@ export const ORCHESTRATION_WORKER_STOP_METHODS = [ // installed the structured host, and both the observation below and the close read it. // Without this a restarted worker answers `unknown` forever and can never be stopped. await runtime.ensureStructuredAgentSessionHost().catch((error: unknown) => { - console.warn( - '[orchestration] structured host install failed before stop', - handle, - error + runtime.structuredAgentSessionLogger.warn( + 'installing the structured host before a worker stop failed', + { scope: 'worker-stop-host-install', dispatchId: params.dispatch, error } ) }) } diff --git a/src/main/runtime/rpc/methods/structured-agent-session-create.ts b/src/main/runtime/rpc/methods/structured-agent-session-create.ts index 1d0899a014df..1a82aaa3bcd7 100644 --- a/src/main/runtime/rpc/methods/structured-agent-session-create.ts +++ b/src/main/runtime/rpc/methods/structured-agent-session-create.ts @@ -173,8 +173,9 @@ export async function createStructuredAgentSessionForWorktree(args: { tabId?: string }): Promise> { const prepared: PreparedStructuredAgentSessionCreate | StructuredCreateRefused = - await resolveUncommittedStructuredCreate(() => - prepareStructuredAgentSessionCreateForWorktree(args) + await resolveUncommittedStructuredCreate( + () => prepareStructuredAgentSessionCreateForWorktree(args), + args.runtime.structuredAgentSessionLogger ) if ('refusal' in prepared) { return { ok: false, refusal: prepared.refusal } diff --git a/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.test.ts b/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.test.ts index 17aadf32a801..97a5a8766f99 100644 --- a/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.test.ts +++ b/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.test.ts @@ -88,6 +88,7 @@ async function create( ...resolvedIntent })), publishStructuredAgentSessionTab: vi.fn(async () => undefined), + structuredAgentSessionLogger: log.logger, ...runtimeOverrides } const replies: RpcResponse[] = [] @@ -115,9 +116,11 @@ function refusalOf(response: RpcResponse): { code: string; message: string } | n return result.ok ? null : (result.refusal ?? null) } +let log: ReturnType + beforeEach(() => { setStructuredAgentSessionHost(hostStub()) - vi.spyOn(console, 'warn').mockImplementation(() => undefined) + log = recordingStructuredAgentSessionLogger() }) afterEach(() => { @@ -155,6 +158,7 @@ describe('a create refused before it commits', () => { expect(refusal?.message).not.toContain('Codex') expect(refusal?.message).toContain('No worktree matches id:workspace-1') expect(attach).not.toHaveBeenCalled() + expect(log.scopes()).toEqual(['create-precommit']) }) it('answers a host that will not install as a definitive envelope', async () => { diff --git a/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.ts b/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.ts index 4038fe9e40d2..7e55725cad7c 100644 --- a/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.ts +++ b/src/main/runtime/rpc/methods/structured-agent-session-precommit-refusal.ts @@ -18,6 +18,7 @@ import { type AgentSessionWireRefusal, type AgentSessionWireRefusalCode } from '../../../../shared/agent-session-wire' +import type { StructuredAgentSessionLogger } from '../../../native-chat/agent-session-wire/structured-agent-session-logger' export type StructuredCreateRefused = { refusal: AgentSessionWireRefusal } @@ -45,7 +46,10 @@ function wireRefusalCode(error: unknown): AgentSessionWireRefusalCode | null { const PRECOMMIT_REFUSAL_MESSAGE = 'Orca cannot open a structured agent chat for this workspace.' -function precommitRefusal(error: unknown): AgentSessionWireRefusal { +function precommitRefusal( + error: unknown, + logger: StructuredAgentSessionLogger +): AgentSessionWireRefusal { // A refusal the host raised keeps its situation; a bare code names none. if (isAgentSessionRefusalError(error)) { return agentSessionRefusalFromReference(error.refusal, PRECOMMIT_REFUSAL_MESSAGE) @@ -57,7 +61,10 @@ function precommitRefusal(error: unknown): AgentSessionWireRefusal { const message = error instanceof Error ? error.message : String(error) // A code-less failure here is often a defect, not a policy answer; the refusal keeps the user // moving, the log keeps the cause findable. Nothing names its situation, so it carries no reason. - console.warn('[agent-session] create refused before it committed anything', error) + logger.warn('a create was refused before it committed anything', { + scope: 'create-precommit', + error + }) return refuseUnclassified( UNCODED_PRECOMMIT_REFUSAL_CODE, `Orca could not prepare a structured agent chat for this workspace: ${message}` @@ -70,11 +77,12 @@ function precommitRefusal(error: unknown): AgentSessionWireRefusal { * longer proves the session does not exist. */ export async function resolveUncommittedStructuredCreate( - prepare: () => Promise + prepare: () => Promise, + logger: StructuredAgentSessionLogger ): Promise { try { return await prepare() } catch (error) { - return { refusal: precommitRefusal(error) } + return { refusal: precommitRefusal(error, logger) } } } diff --git a/src/main/runtime/rpc/methods/structured-agent-session.ts b/src/main/runtime/rpc/methods/structured-agent-session.ts index e0d24119086c..cd8ac6abd5a0 100644 --- a/src/main/runtime/rpc/methods/structured-agent-session.ts +++ b/src/main/runtime/rpc/methods/structured-agent-session.ts @@ -183,7 +183,7 @@ export const STRUCTURED_AGENT_SESSION_METHODS = [ } const { host, attachParams } = await resolveClientSuppliedAttach(params, ctx) return { host, attachParams, tab: null } - }) + }, ctx.runtime.structuredAgentSessionLogger) if ('refusal' in prepared) { return { ok: false, refusal: prepared.refusal } } diff --git a/src/main/runtime/rpc/methods/structured-worker-stop-receipt.test.ts b/src/main/runtime/rpc/methods/structured-worker-stop-receipt.test.ts index d6f41acdeee9..8a1e583ba18a 100644 --- a/src/main/runtime/rpc/methods/structured-worker-stop-receipt.test.ts +++ b/src/main/runtime/rpc/methods/structured-worker-stop-receipt.test.ts @@ -126,4 +126,20 @@ describe('worker-stop on a structured worker this runtime cannot reach', () => { } ) }) + + it('reports a failed host install by dispatch, never by the worker handle', async () => { + const dispatchId = startStructuredWorker() + const failure = new Error('journal database unavailable') + vi.spyOn(runtime, 'ensureStructuredAgentSessionHost').mockRejectedValue(failure) + const warn = vi.spyOn(runtime.structuredAgentSessionLogger, 'warn') + + await expect(call('orchestration.workerStop', { dispatch: dispatchId })).resolves.toMatchObject( + { processAction: 'none', state: 'stop_unknown' } + ) + expect(warn).toHaveBeenCalledOnce() + const fields = warn.mock.calls[0][1] + // The handle is a bearer credential; the trace file and diagnostic bundle must not carry it. + expect(fields).toEqual({ scope: 'worker-stop-host-install', dispatchId, error: failure }) + expect(JSON.stringify(fields)).not.toContain(HANDLE) + }) }) diff --git a/src/main/runtime/rpc/methods/structured-worker-tab-retirement.test.ts b/src/main/runtime/rpc/methods/structured-worker-tab-retirement.test.ts index cee7adf64256..4dfb7b333b29 100644 --- a/src/main/runtime/rpc/methods/structured-worker-tab-retirement.test.ts +++ b/src/main/runtime/rpc/methods/structured-worker-tab-retirement.test.ts @@ -18,6 +18,7 @@ import { structuredWorkerProcessIncarnation, type StructuredWorkerIdentity } from '../../structured-worker-identity' +import { recordingStructuredAgentSessionLogger } from '../../../native-chat/agent-session-wire/structured-agent-session-logger-test-support' const createSpy = vi.fn() vi.mock('./structured-agent-session-create', () => ({ @@ -160,18 +161,23 @@ describe('structured worker stop retires the chat tab', () => { it('cannot turn a proven stop into a retained one when the prune throws', async () => { installHost() const identity = registerIdentity() + const log = recordingStructuredAgentSessionLogger() const runtime = { forgetStructuredSessionMail: vi.fn(), retireStructuredAgentSessionTabFromSnapshot: vi.fn(() => { throw new Error('snapshot is wedged') - }) - } as unknown as OrcaRuntimeService + }), + structuredAgentSessionLogger: log.logger + } await expect(stopStructuredWorker(identity, 'd1', runtime)).resolves.toEqual({ stopped: true, closeAttempted: true }) expect(runtime.retireStructuredAgentSessionTabFromSnapshot).toHaveBeenCalledWith(SESSION) + expect(log.entries.map(({ fields }) => [fields.scope, fields.sessionId])).toEqual([ + ['chat-tab-retire', SESSION] + ]) }) it('settles a runtime that has no tab surface at all', async () => { diff --git a/src/main/runtime/structured-agent-session-close.ts b/src/main/runtime/structured-agent-session-close.ts index 16bf8cce71d7..de8b44cc0acd 100644 --- a/src/main/runtime/structured-agent-session-close.ts +++ b/src/main/runtime/structured-agent-session-close.ts @@ -30,7 +30,9 @@ export type StructuredAgentSessionCloseOutcome = { export type StructuredAgentSessionCloseOptions = { runtime?: Pick< OrcaRuntimeService, - 'forgetStructuredSessionMail' | 'retireStructuredAgentSessionTabFromSnapshot' + | 'forgetStructuredSessionMail' + | 'retireStructuredAgentSessionTabFromSnapshot' + | 'structuredAgentSessionLogger' > /** * Runs after the close is issued and BEFORE the proof is read. diff --git a/src/main/runtime/structured-agent-session-journal-open.ts b/src/main/runtime/structured-agent-session-journal-open.ts index 54c27fbfe963..65d5d1412ec1 100644 --- a/src/main/runtime/structured-agent-session-journal-open.ts +++ b/src/main/runtime/structured-agent-session-journal-open.ts @@ -37,12 +37,15 @@ export async function openStructuredAgentSessionJournalDatabase(args: { logger: StructuredAgentSessionLogger }): Promise { try { - const opened = await JournalHostDatabase.open(args.stateDirectory, async () => - legacyAgentSessionRecordImport( - await readLegacyAgentSessionRecords(args.stateDirectory, args.hostId), - args.hostId, - (report) => reportLegacyRecordImport(args.logger, report) - ) + const opened = await JournalHostDatabase.open( + args.stateDirectory, + async () => + legacyAgentSessionRecordImport( + await readLegacyAgentSessionRecords(args.stateDirectory, args.hostId), + args.hostId, + (report) => reportLegacyRecordImport(args.logger, report) + ), + args.logger ) recordStructuredAgentSessionHostInstallRefusal(null) lastLoggedOpenFailure = null diff --git a/src/main/runtime/structured-agent-session-runtime.test.ts b/src/main/runtime/structured-agent-session-runtime.test.ts index f572e8909833..cb0c7f436ed3 100644 --- a/src/main/runtime/structured-agent-session-runtime.test.ts +++ b/src/main/runtime/structured-agent-session-runtime.test.ts @@ -29,6 +29,9 @@ import { stopStructuredAgentSessionRuntime } from './structured-agent-session-runtime' import { createStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const HOST_ID = 'local' @@ -76,7 +79,7 @@ describe('structured agent-session store presence', () => { legacyRecords: JournalLegacyRecordImport = NO_LEGACY_JOURNAL_RECORDS ): Promise { profile = await mkdtemp(join(tmpdir(), 'orca-session-presence-')) - return JournalHostDatabase.openWith(profile, legacyRecords) + return JournalHostDatabase.openWith(profile, legacyRecords, TEST_LOGGER) } async function writeRecordsFile(): Promise { diff --git a/src/main/runtime/structured-agent-session-runtime.ts b/src/main/runtime/structured-agent-session-runtime.ts index 3785fdeaf5ce..684d689203cf 100644 --- a/src/main/runtime/structured-agent-session-runtime.ts +++ b/src/main/runtime/structured-agent-session-runtime.ts @@ -266,6 +266,7 @@ async function installOnJournal( ...(deps.openCodexConnection ? { openConnection: deps.openCodexConnection } : {}), ...(deps.readProcessStartTime ? { readProcessStartTime: deps.readProcessStartTime } : {}), modelCatalog: agentModelCatalogStore, + logger: deps.logger, onChildWorkEvidence: (sessionId, evidence) => host?.publishChildWorkEvidence(sessionId, evidence), onDispatchSettledLate, @@ -278,6 +279,7 @@ async function installOnJournal( }) const claude = createStructuredClaudeRuntimeAdapter({ store, + logger: deps.logger, resolveWorkspacePath: deps.resolveWorkspacePath, ...(deps.resolveClaudeCommand ? { resolveClaudeCommand: deps.resolveClaudeCommand } : {}), ...(deps.resolveClaudeLaunchEnv ? { resolveClaudeLaunchEnv: deps.resolveClaudeLaunchEnv } : {}), diff --git a/src/main/runtime/structured-agent-session-tab-retirement.ts b/src/main/runtime/structured-agent-session-tab-retirement.ts index aee5ef6d719d..b24128bbe65c 100644 --- a/src/main/runtime/structured-agent-session-tab-retirement.ts +++ b/src/main/runtime/structured-agent-session-tab-retirement.ts @@ -10,6 +10,7 @@ import type { RuntimeMobileSessionSnapshotTab, RuntimeMobileSessionTabsSnapshot } from '../../shared/runtime-types' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' import { structuredAgentSessionTabId } from '../../shared/structured-agent-session-projection' /** The snapshot's tab for a structured session, matched by session id and by published tab id. */ @@ -68,12 +69,19 @@ export function retireStructuredAgentSessionTabFrom( export function retireSettledStructuredWorkerTab( sessionId: string, runtime: - | { retireStructuredAgentSessionTabFromSnapshot?: (sessionId: string) => boolean } + | { + retireStructuredAgentSessionTabFromSnapshot?: (sessionId: string) => boolean + structuredAgentSessionLogger: StructuredAgentSessionLogger + } | undefined ): void { try { runtime?.retireStructuredAgentSessionTabFromSnapshot?.(sessionId) } catch (error) { - console.warn('[orchestration] structured worker tab retirement failed', sessionId, error) + runtime?.structuredAgentSessionLogger.warn('retiring a settled chat tab failed', { + scope: 'chat-tab-retire', + sessionId, + error + }) } } diff --git a/src/main/runtime/structured-claude-pending-rewind.test.ts b/src/main/runtime/structured-claude-pending-rewind.test.ts index 47fa6d201009..2e2f6e3dce77 100644 --- a/src/main/runtime/structured-claude-pending-rewind.test.ts +++ b/src/main/runtime/structured-claude-pending-rewind.test.ts @@ -26,6 +26,8 @@ import { createStructuredClaudeRuntimeAdapter } from './structured-claude-runtim import { openTestJournalHostDatabase } from '../native-chat/agent-session-journal/journal-host-database-test-support' import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger + const caller = { callerKey: 'desktop' } const PROVIDER_SESSION_ID = claudeSessionIdForOrcaSession(HOST_TEST_SESSION) const TARGET = agentJournalItemKey({ @@ -112,6 +114,7 @@ beforeEach(async () => { store = await openTestAgentSessionRecordStore(directory) claude = fakeClaude({ initSessionId: PROVIDER_SESSION_ID }) adapter = createStructuredClaudeRuntimeAdapter({ + logger: TEST_LOGGER, store, resolveWorkspacePath: async (id) => `/repos/${id}`, resolveClaudeCommand: () => '/usr/local/bin/claude', diff --git a/src/main/runtime/structured-claude-runtime-adapter.ts b/src/main/runtime/structured-claude-runtime-adapter.ts index 9024c65b503d..b7ffca0e9042 100644 --- a/src/main/runtime/structured-claude-runtime-adapter.ts +++ b/src/main/runtime/structured-claude-runtime-adapter.ts @@ -16,10 +16,12 @@ import { } from './agent-session-provider-handle-transition' import type { ClaudeManagedAccountGateSettings } from '../native-chat/claude-structured-managed-account-support' import type { AgentSessionRecordStore } from './agent-session-record-store' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' import { ClaudeAtRestCommandCatalog } from '../claude/claude-at-rest-commands' export type StructuredClaudeRuntimeAdapterDeps = { store: AgentSessionRecordStore + logger: StructuredAgentSessionLogger resolveWorkspacePath: (workspaceId: string) => Promise resolveClaudeCommand?: () => string resolveClaudeLaunchEnv?: () => Promise> | Record @@ -75,10 +77,12 @@ export function createStructuredClaudeRuntimeAdapter( const { store } = deps return new ClaudeStructuredSessionAdapter({ atRestCommands: new ClaudeAtRestCommandCatalog({ + logger: deps.logger, resolveWorkspacePath: deps.resolveWorkspacePath }), resolveLaunch: createClaudeStructuredLaunchResolver({ store, + logger: deps.logger, resolveWorkspacePath: deps.resolveWorkspacePath, resolveCommand: deps.resolveClaudeCommand ?? resolveClaudeCommand, ...(deps.resolveClaudeLaunchEnv ? { resolveEnv: deps.resolveClaudeLaunchEnv } : {}), @@ -133,6 +137,7 @@ export function createStructuredClaudeRuntimeAdapter( ...(deps.onChildWorkEvidence ? { onChildWorkEvidence: deps.onChildWorkEvidence } : {}), ...(deps.openClaudeConnection ? { openConnection: deps.openClaudeConnection } : {}), ...(deps.readProcessStartTime ? { readProcessStartTime: deps.readProcessStartTime } : {}), - ...(deps.modelCatalog ? { modelCatalog: deps.modelCatalog } : {}) + ...(deps.modelCatalog ? { modelCatalog: deps.modelCatalog } : {}), + logger: deps.logger }) } diff --git a/src/main/runtime/structured-claude-scripted-runtime-test-support.ts b/src/main/runtime/structured-claude-scripted-runtime-test-support.ts index 7a69cbe9c86d..b0e71082e051 100644 --- a/src/main/runtime/structured-claude-scripted-runtime-test-support.ts +++ b/src/main/runtime/structured-claude-scripted-runtime-test-support.ts @@ -75,7 +75,7 @@ export function createScriptedClaudeRuntime(sessionIds: readonly string[]) { let root: string | null = null let operations = 0 - const openConnection: typeof openClaudeStreamJsonConnection = async (launch, handlers = {}) => { + const openConnection: typeof openClaudeStreamJsonConnection = async (launch, handlers) => { const providerSessionId = String(launch.options.sessionId ?? launch.options.resume) const sessionId = sessionIds.find( (candidate) => claudeSessionIdForOrcaSession(candidate) === providerSessionId diff --git a/src/main/runtime/structured-session-child-identity-env.test.ts b/src/main/runtime/structured-session-child-identity-env.test.ts index 1289e979ad63..c09df77b0a6f 100644 --- a/src/main/runtime/structured-session-child-identity-env.test.ts +++ b/src/main/runtime/structured-session-child-identity-env.test.ts @@ -1,6 +1,9 @@ import { join } from 'node:path' import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' import { installFakeAppEnvironment } from '../../../config/scripts/vitest-host-ports-setup' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const shim = vi.hoisted(() => ({ ensureLinuxTerminalOrcaCliShimDir: vi.fn() })) vi.mock('../cli/linux-terminal-orca-cli-shim', () => shim) @@ -63,7 +66,7 @@ describe('structuredSessionChildIdentityEnv', () => { pinPlatform('linux') installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) const childEnv = { PATH: '/usr/bin' } - const env = structuredSessionChildIdentityEnv(SESSION_ID, childEnv) + const env = structuredSessionChildIdentityEnv(SESSION_ID, childEnv, TEST_LOGGER) expect(env).toEqual({ PATH: `${SHIM_DIR}:/usr/bin`, ORCA_AGENT_SESSION_ID: SESSION_ID, @@ -81,10 +84,14 @@ describe('structuredSessionChildIdentityEnv', () => { it('replaces an id inherited from an Orca launched inside another session', () => { installFakeAppEnvironment({ isPackaged: () => false, getPath: () => USER_DATA }) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { - ORCA_AGENT_SESSION_ID: 'a0b1c2d3-0000-4000-8000-00000000abcd', - PATH: '/usr/bin' - }) + const env = structuredSessionChildIdentityEnv( + SESSION_ID, + { + ORCA_AGENT_SESSION_ID: 'a0b1c2d3-0000-4000-8000-00000000abcd', + PATH: '/usr/bin' + }, + TEST_LOGGER + ) expect(env.ORCA_AGENT_SESSION_ID).toBe(SESSION_ID) }) @@ -93,7 +100,7 @@ describe('structuredSessionChildIdentityEnv', () => { // one identity; the handle stays for the handle-based surfaces outside orchestration. installFakeAppEnvironment({ isPackaged: () => false, getPath: () => USER_DATA }) const handle = registerWorker() - const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }) + const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }, TEST_LOGGER) expect(env.ORCA_AGENT_SESSION_ID).toBe(SESSION_ID) expect(env.ORCA_TERMINAL_HANDLE).toBe(handle) }) @@ -110,7 +117,11 @@ describe('structuredSessionChildIdentityEnv', () => { // installs as `orca-ide` on Linux (stablyai/orca#7904) — and the dispatch hangs to timeout. pinPlatform('linux') installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin:/bin' }) + const env = structuredSessionChildIdentityEnv( + SESSION_ID, + { PATH: '/usr/bin:/bin' }, + TEST_LOGGER + ) expect(env.ORCA_CLI_COMMAND).toBe(join(SHIM_DIR, 'orca')) expect(env.PATH).toBe(`${SHIM_DIR}:/usr/bin:/bin`) }) @@ -118,7 +129,7 @@ describe('structuredSessionChildIdentityEnv', () => { it('on packaged macOS, through the bundled CLI dir', () => { pinPlatform('darwin') installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }) + const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }, TEST_LOGGER) expect(env.PATH).toBe(`${join(RESOURCES, 'bin')}:/usr/bin`) expect(env.ORCA_CLI_COMMAND).toBe(join(RESOURCES, 'bin', 'orca')) }) @@ -126,7 +137,11 @@ describe('structuredSessionChildIdentityEnv', () => { it('on packaged Windows, through the bundled CLI dir under the env block spelling', () => { pinPlatform('win32') installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { Path: 'C:\\Windows' }) + const env = structuredSessionChildIdentityEnv( + SESSION_ID, + { Path: 'C:\\Windows' }, + TEST_LOGGER + ) expect(env.Path).toBe(`${join(RESOURCES, 'bin')};C:\\Windows`) expect(env.PATH).toBeUndefined() // The native launcher: `orca.cmd` refuses message bodies cmd.exe would mangle. @@ -136,7 +151,7 @@ describe('structuredSessionChildIdentityEnv', () => { it('unpackaged, through the dev launcher dir', () => { pinPlatform('darwin') installFakeAppEnvironment({ isPackaged: () => false, getPath: () => USER_DATA }) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }) + const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }, TEST_LOGGER) expect(env.PATH).toBe(`${join(USER_DATA, 'cli', 'bin')}:/usr/bin`) expect(env.ORCA_CLI_COMMAND).toBe(join(USER_DATA, 'cli', 'bin', 'orca-dev')) }) @@ -148,16 +163,22 @@ describe('structuredSessionChildIdentityEnv', () => { pinPlatform('linux') installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) shim.ensureLinuxTerminalOrcaCliShimDir.mockReturnValue(null) - vi.spyOn(console, 'warn').mockImplementation(() => {}) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { - PATH: '/usr/bin', - ORCA_CLI_COMMAND: '/Applications/Other Orca.app/Contents/Resources/bin/orca', - ORCA_USER_DATA_PATH: '/data/other-orca' - }) + const log = recordingStructuredAgentSessionLogger() + const env = structuredSessionChildIdentityEnv( + SESSION_ID, + { + PATH: '/usr/bin', + ORCA_CLI_COMMAND: '/Applications/Other Orca.app/Contents/Resources/bin/orca', + ORCA_USER_DATA_PATH: '/data/other-orca' + }, + log.logger + ) expect(env).not.toHaveProperty('ORCA_CLI_COMMAND') expect(env.PATH).toBe('/usr/bin') expect(env.ORCA_USER_DATA_PATH).toBe(USER_DATA) - expect(console.warn).toHaveBeenCalledOnce() + expect(log.entries.map(({ fields }) => fields)).toEqual([ + { scope: 'child-cli-launcher', sessionId: SESSION_ID } + ]) }) it('never puts a pane key in the child environment', () => { @@ -166,7 +187,7 @@ describe('structuredSessionChildIdentityEnv', () => { pinPlatform('linux') installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) registerWorker() - const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }) + const env = structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }, TEST_LOGGER) expect(env.ORCA_PANE_KEY).toBeUndefined() expect(Object.keys(env).filter((key) => key.includes('PANE'))).toEqual([]) }) @@ -187,7 +208,8 @@ describe('structuredSessionChildIdentityEnv', () => { installFakeAppEnvironment({ isPackaged: () => true, getPath: () => USER_DATA }) registerWorker() expect( - structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }).ORCA_CLI_COMMAND + structuredSessionChildIdentityEnv(SESSION_ID, { PATH: '/usr/bin' }, TEST_LOGGER) + .ORCA_CLI_COMMAND ).not.toBe('orca-ide') }) }) diff --git a/src/main/runtime/structured-session-child-identity-env.ts b/src/main/runtime/structured-session-child-identity-env.ts index 4d3e85c34140..fead507f8082 100644 --- a/src/main/runtime/structured-session-child-identity-env.ts +++ b/src/main/runtime/structured-session-child-identity-env.ts @@ -49,10 +49,12 @@ import { ORCA_AGENT_SESSION_ID_ENV } from '../../shared/agent-session-caller-env import { ORCA_STRUCTURED_SESSION_ENV } from '../../shared/structured-session-marker' import { prependOrcaCliDirToChildPath } from '../cli/orca-cli-child-path' import { structuredWorkerIdentities } from './structured-worker-identity' +import type { StructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger' export function structuredSessionChildIdentityEnv( sessionId: string, - childEnv: Record + childEnv: Record, + logger: StructuredAgentSessionLogger ): Record { const identity = structuredWorkerIdentities.getBySessionId(sessionId) const env: Record = { @@ -61,7 +63,7 @@ export function structuredSessionChildIdentityEnv( [ORCA_AGENT_SESSION_ID_ENV]: sessionId, [ORCA_STRUCTURED_SESSION_ENV]: '1' } - applyThisAppCli(env) + applyThisAppCli(env, sessionId, logger) return env } @@ -69,7 +71,11 @@ export function structuredSessionChildIdentityEnv( * A host with no app environment installed — a plain-Node fork, or a unit test — has no userData * root to resolve, and inventing one would write a shim into the wrong directory. */ -function applyThisAppCli(env: Record): void { +function applyThisAppCli( + env: Record, + sessionId: string, + logger: StructuredAgentSessionLogger +): void { delete env.ORCA_CLI_COMMAND if (!hasAppEnvironment()) { return @@ -86,8 +92,9 @@ function applyThisAppCli(env: Record): void { if (launcher) { env.ORCA_CLI_COMMAND = launcher } else { - console.warn( - "[structured-session] This app's CLI launcher did not resolve; the session's child has no ORCA_CLI_COMMAND." - ) + logger.warn("this app's CLI launcher did not resolve; the child has no ORCA_CLI_COMMAND", { + scope: 'child-cli-launcher', + sessionId + }) } } diff --git a/src/main/runtime/structured-session-login-shell-test-harness.ts b/src/main/runtime/structured-session-login-shell-test-harness.ts index 943dfe0f4d3d..fadcdb4fcdd4 100644 --- a/src/main/runtime/structured-session-login-shell-test-harness.ts +++ b/src/main/runtime/structured-session-login-shell-test-harness.ts @@ -10,6 +10,9 @@ import { join } from 'node:path' import { installFakeAppEnvironment } from '../../../config/scripts/vitest-host-ports-setup' import { runProcess } from '../../shared/child-process/run-process' import { structuredSessionChildIdentityEnv } from './structured-session-child-identity-env' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION_ID = 'f7a1c0de-1111-4222-8333-444455556666' @@ -40,7 +43,11 @@ export function createLoginShellHarness(): LoginShellHarness { writeFileSync(join(home, '.zprofile'), prependGlobal) writeFileSync(join(home, '.bash_profile'), prependGlobal) installFakeAppEnvironment({ isPackaged: () => false, getPath: () => userData }) - const env = structuredSessionChildIdentityEnv(SESSION_ID, { HOME: home, PATH: '/usr/bin:/bin' }) + const env = structuredSessionChildIdentityEnv( + SESSION_ID, + { HOME: home, PATH: '/usr/bin:/bin' }, + TEST_LOGGER + ) return { run: async (spec) => (await runProcess({ ...spec, env })).stdout, dispose: () => rmSync(root, { recursive: true, force: true }) diff --git a/src/main/runtime/structured-session-mail-redrive-wiring.test.ts b/src/main/runtime/structured-session-mail-redrive-wiring.test.ts index d7779112cc63..4dfb3db1e44c 100644 --- a/src/main/runtime/structured-session-mail-redrive-wiring.test.ts +++ b/src/main/runtime/structured-session-mail-redrive-wiring.test.ts @@ -50,7 +50,7 @@ describe("the runtime's own structured host install", () => { const closed = new OrchestrationDb(':memory:') closed.close() vi.spyOn(runtime, 'getExistingOrchestrationDb').mockReturnValue(closed) - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const warn = vi.spyOn(runtime.structuredAgentSessionLogger, 'warn').mockImplementation(() => {}) expect(() => runtime.onStructuredSessionStatusForMail({ sessionId: '4a1f6c2e-8b3d-4e7a-9c15-0d2b6e8f1a37', @@ -58,8 +58,11 @@ describe("the runtime's own structured host install", () => { }) ).not.toThrow() expect(warn).toHaveBeenCalledWith( - '[orchestration] structured session mail redrive failed', - expect.objectContaining({ sessionId: '4a1f6c2e-8b3d-4e7a-9c15-0d2b6e8f1a37' }) + 'a structured session mail redrive failed', + expect.objectContaining({ + scope: 'mail-redrive', + sessionId: '4a1f6c2e-8b3d-4e7a-9c15-0d2b6e8f1a37' + }) ) }) }) diff --git a/src/main/runtime/structured-session-worktree-teardown.test.ts b/src/main/runtime/structured-session-worktree-teardown.test.ts index f33d7889b31f..ea48f57d568e 100644 --- a/src/main/runtime/structured-session-worktree-teardown.test.ts +++ b/src/main/runtime/structured-session-worktree-teardown.test.ts @@ -1,6 +1,7 @@ import { beforeEach, describe, expect, it, vi } from 'vitest' import type { AgentSessionRecord } from '../../shared/agent-session-record' import type { IPtyProvider } from '../providers/types' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' const hostRef: { current: unknown } = { current: null } @@ -473,6 +474,21 @@ describe('worktree teardown and structured agent sessions', () => { expect(isProvenLiveStructuredSessionRemovalError(error as string)).toBe(true) }) + it("records a forced removal's unclosed sessions through the runtime's chat logger", async () => { + const logged = recordingStructuredAgentSessionLogger() + installHost({ records: [record('s1', WORKTREE)], stuck: new Set(['s1']) }) + await killAllProcessesForWorktree(WORKTREE, { + ...destructiveDeps({ allowUnverifiedStop: true }), + runtime: runtimeDouble({ structuredAgentSessionLogger: logged.logger }) + }) + expect(logged.entries).toHaveLength(1) + expect(logged.entries[0].message).toContain('still live: 1 agent session (claude)') + expect(logged.entries[0].fields).toEqual({ + scope: 'worktree-forced-removal', + sessionIds: ['s1'] + }) + }) + it('still reports what it closed when a forced removal skips the PTY verdict', async () => { // A sweep that fails outright short-circuits the per-PTY verdict — but not the structured // close that already ran, so the count has to survive that return or the removal log claims diff --git a/src/main/runtime/structured-session-worktree-teardown.ts b/src/main/runtime/structured-session-worktree-teardown.ts index 047b4a216445..e90780814a0e 100644 --- a/src/main/runtime/structured-session-worktree-teardown.ts +++ b/src/main/runtime/structured-session-worktree-teardown.ts @@ -48,7 +48,9 @@ export type UnclosedStructuredSession = StructuredSessionInWorkspace & { export type StructuredWorktreeSweepRuntime = Pick< OrcaRuntimeService, - 'forgetStructuredSessionMail' | 'retireStructuredAgentSessionTabFromSnapshot' + | 'forgetStructuredSessionMail' + | 'retireStructuredAgentSessionTabFromSnapshot' + | 'structuredAgentSessionLogger' > /** diff --git a/src/main/runtime/structured-worker-identity.test.ts b/src/main/runtime/structured-worker-identity.test.ts index 17ba897de479..4c21b07a80db 100644 --- a/src/main/runtime/structured-worker-identity.test.ts +++ b/src/main/runtime/structured-worker-identity.test.ts @@ -20,6 +20,9 @@ import { } from './structured-worker-identity' import type { AgentSessionRecord } from '../../shared/agent-session-record' import type { ExecutionHostId } from '../../shared/execution-host' +import { recordingStructuredAgentSessionLogger } from '../native-chat/agent-session-wire/structured-agent-session-logger-test-support' + +const TEST_LOGGER = recordingStructuredAgentSessionLogger().logger const SESSION_ID = 'a1b2c3d4-e5f6-4a7b-8c9d-0e1f2a3b4c5d' @@ -300,7 +303,7 @@ describe('structured workers stay outside the PTY-only fail-closed paths', () => hostScope: { kind: 'local', hostId: 'local' } }) try { - const env = structuredSessionChildIdentityEnv(SESSION_ID, {}) + const env = structuredSessionChildIdentityEnv(SESSION_ID, {}, TEST_LOGGER) // Registered, so the worker's handle is present; without it the pane-key assertion would pass // for the wrong reason. expect(env.ORCA_TERMINAL_HANDLE).toBe(handle) diff --git a/src/main/runtime/worktree-teardown.ts b/src/main/runtime/worktree-teardown.ts index 417bf4ff1f76..0fc69ac0c1ab 100644 --- a/src/main/runtime/worktree-teardown.ts +++ b/src/main/runtime/worktree-teardown.ts @@ -404,9 +404,16 @@ async function sweepStructuredSessions( // verbatim, like the unstopped-PTY warn above: this line is the only record a forced removal // leaves, and appending "still attached" asserted the live verdict over sessions the sweep had // just said it could not confirm either way. - console.warn( - `[worktree-teardown] forcing removal of ${worktreeId}${UNSTOPPED_PTY_DETAIL_SEPARATOR}${describeUnclosedStructuredSessions(unstopped)}` - ) + const forced = `forcing removal of ${worktreeId}${UNSTOPPED_PTY_DETAIL_SEPARATOR}${describeUnclosedStructuredSessions(unstopped)}` + const logger = deps.runtime?.structuredAgentSessionLogger + if (logger) { + logger.warn(forced, { + scope: 'worktree-forced-removal', + sessionIds: unstopped.map((session) => session.sessionId) + }) + } else { + console.warn(`[worktree-teardown] ${forced}`) + } // A best-effort or forced removal still discards the workspace when a live close remains // unproven. Its close path intentionally leaves the live snapshot tab in place, so carry those // sessions into the post-removal retirement pass alongside the detached members.