diff --git a/src/main/claude/claude-api-retry-row.test.ts b/src/main/claude/claude-api-retry-row.test.ts index a1c8da60cb7d..f36f54396fbf 100644 --- a/src/main/claude/claude-api-retry-row.test.ts +++ b/src/main/claude/claude-api-retry-row.test.ts @@ -54,7 +54,7 @@ async function statusRowsFor(frames: Record[]) { now: () => 1_700_000_000_000, mintEpoch: () => 'epoch-1' }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: vi.fn() }) const translator = createClaudeJournalTranslator({ sink: deferred.sink, fallbackIdPrefix: '1' }) for (const frame of frames) { diff --git a/src/main/claude/claude-context-usage-restart.test.ts b/src/main/claude/claude-context-usage-restart.test.ts index 4359799272e4..4c550fd62bf5 100644 --- a/src/main/claude/claude-context-usage-restart.test.ts +++ b/src/main/claude/claude-context-usage-restart.test.ts @@ -112,7 +112,7 @@ async function openJournal(): Promise { /** One acquisition: a fresh sink and translator over the session's journal. */ function acquire(journal: AgentSessionJournal) { - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const translator = createClaudeJournalTranslator({ sink: deferred.sink, coalesceMs: 0 }) deferred.bind({ journal, fence: 1, publish: () => {} }) const answers: ((value: unknown) => void)[] = [] diff --git a/src/main/claude/claude-context-usage-unloaded-turn.test.ts b/src/main/claude/claude-context-usage-unloaded-turn.test.ts index ed76a788c186..f7d1701c1d45 100644 --- a/src/main/claude/claude-context-usage-unloaded-turn.test.ts +++ b/src/main/claude/claude-context-usage-unloaded-turn.test.ts @@ -56,7 +56,7 @@ async function openJournal(): Promise { } function translate(journal: AgentSessionJournal) { - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const translator = createClaudeJournalTranslator({ sink: deferred.sink, coalesceMs: 0 }) deferred.bind({ journal, fence: 1, publish: () => {} }) const settle = async (): Promise => { diff --git a/src/main/claude/claude-stream-json-connection.test.ts b/src/main/claude/claude-stream-json-connection.test.ts index 7d198c5a5de5..dae4fce8e336 100644 --- a/src/main/claude/claude-stream-json-connection.test.ts +++ b/src/main/claude/claude-stream-json-connection.test.ts @@ -385,7 +385,7 @@ describe('Claude stream-json connection', () => { now: () => 1_700_000_000_000, mintEpoch: () => 'epoch-1' }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: vi.fn() }) const translator = createClaudeJournalTranslator({ sink: deferred.sink }) let settled = false diff --git a/src/main/claude/claude-structured-command-dispatch.ts b/src/main/claude/claude-structured-command-dispatch.ts index 3d03c18178c3..12b77bde4868 100644 --- a/src/main/claude/claude-structured-command-dispatch.ts +++ b/src/main/claude/claude-structured-command-dispatch.ts @@ -10,7 +10,8 @@ import type { ClaudeSession } from './claude-structured-session-state' * makes the command's turn the open one before the send, and that same result ends it. */ export async function dispatchClaudeCommand( session: ClaudeSession, - command: StructuredAgentSessionCommandRun + command: StructuredAgentSessionCommandRun, + sessionId: string ): Promise { const sentUuid = randomUUID() session.translator?.beginCommand({ @@ -20,6 +21,7 @@ export async function dispatchClaudeCommand( }) try { const admission = await dispatchClaudeTurn(session, { + sessionId, clientMessageId: command.clientMessageId, body: { kind: 'message', role: 'user', blocks: [{ type: 'text', text: '/compact' }] }, ...(command.running.requestedAt === undefined 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..89fc95876a37 100644 --- a/src/main/claude/claude-structured-dispatch-attachment-rejection.test.ts +++ b/src/main/claude/claude-structured-dispatch-attachment-rejection.test.ts @@ -158,6 +158,7 @@ describe('Claude structured dispatch attachment rejections', () => { await expect( dispatchClaudeTurn(session, { + sessionId: 'session-1', clientMessageId: 'client-1', body: userMessage([{ type: 'image-ref', path }]) }) @@ -167,9 +168,10 @@ describe('Claude structured dispatch attachment rejections', () => { rejection: { kind: 'attachmentUnreadable' } }) expect(session.connection.send).not.toHaveBeenCalled() - // The row drops the error, so the log is the only place left to find why. + // The row drops the error, so the trace is the only place left to find why. expect(warn).toHaveBeenCalledWith( - '[claude-dispatch] attachment could not be read:', + '[agent-session] claude-attachment-read failed', + { sessionId: 'session-1', providerSessionId: session.providerSessionId }, 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..bfd5f7089f5f 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 { traceAgentSessionError } from '../observability/agent-session-error-trace' /** Orca refused the message's content, as opposed to failing to read an attachment. */ export class ClaudeDispatchContentError extends Error { @@ -47,12 +48,20 @@ 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, + ids: { sessionId?: string; providerSessionId: string } +): 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) + // The row says only that it could not be read; why belongs in the trace. + traceAgentSessionError({ + step: 'claude-attachment-read', + sessionId: ids.sessionId, + error, + detail: { providerSessionId: ids.providerSessionId } + }) return claudeDispatchRejection(agentSessionFailureFact('attachmentUnreadable')) } diff --git a/src/main/claude/claude-structured-dispatch.test.ts b/src/main/claude/claude-structured-dispatch.test.ts index 92ae0253711a..4bd0daafbbbd 100644 --- a/src/main/claude/claude-structured-dispatch.test.ts +++ b/src/main/claude/claude-structured-dispatch.test.ts @@ -406,15 +406,16 @@ describe('Claude structured dispatch image limits', () => { const body = userMessage([{ type: 'text', text: 'retry me' }]) await expect( - dispatchClaudeTurn(session, { clientMessageId: 'client-1', body }) + dispatchClaudeTurn(session, { sessionId: 'session-1', clientMessageId: 'client-1', body }) ).resolves.toEqual({ state: 'rejected', reason: 'provider_write_failed', rejection: { kind: 'writeFailed' } }) - // The row keeps only the marker; why the write failed goes to the log. + // The row keeps only the marker; why the write failed goes to the trace. expect(warn).toHaveBeenCalledWith( - '[claude-dispatch] message could not be handed to Claude:', + '[agent-session] claude-dispatch-write failed', + { sessionId: 'session-1', providerSessionId: session.providerSessionId }, expect.objectContaining({ message: expect.stringContaining('broken pipe') }) ) warn.mockRestore() diff --git a/src/main/claude/claude-structured-dispatch.ts b/src/main/claude/claude-structured-dispatch.ts index c208cceccdbf..4ba20202f0e1 100644 --- a/src/main/claude/claude-structured-dispatch.ts +++ b/src/main/claude/claude-structured-dispatch.ts @@ -19,6 +19,7 @@ import { import { dispatchWriteOutcomeUnknownReason } from '../native-chat/agent-session-journal/journal-dispatch-doubt-reasons' import { DISPATCH_REJECTED_QUEUE_FULL } from '../../shared/structured-agent-session-dispatch-rejection' import { agentSessionFailureFact } from '../../shared/agent-session-failure' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' import type { AgentJournalDispatchRejection } from '../../shared/agent-session-failure-words' import { claudeUnwrittenUserMessageError, @@ -71,15 +72,26 @@ 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) +/** The row keeps only the marker released clients hide; why the write failed belongs in the trace. */ +function claudeWriteFailureRejection( + session: ClaudeSession, + sessionId: string | undefined, + error: unknown +): AgentJournalDispatchRejection { + traceAgentSessionError({ + step: 'claude-dispatch-write', + sessionId, + error, + detail: { providerSessionId: session.providerSessionId } + }) return claudeDispatchRejection(agentSessionFailureFact('writeFailed')) } export async function dispatchClaudeTurn( session: ClaudeSession, input: { + /** Orca's session, which a trace record is filed under. */ + sessionId?: string clientMessageId?: string body: AgentJournalMessageItem requestedAt?: number @@ -92,7 +104,13 @@ export async function dispatchClaudeTurn( try { content = await claudeDispatchMessageContent(input.body) } catch (error) { - return { state: 'rejected', ...claudeDispatchContentRejection(error) } + return { + state: 'rejected', + ...claudeDispatchContentRejection(error, { + sessionId: input.sessionId, + providerSessionId: session.providerSessionId + }) + } } if (session.dispatchWaiters.length >= MAX_ACTIVE_DISPATCH_WAITERS) { return { state: 'rejected', ...claudeDispatchRejection(agentSessionFailureFact('queueFull')) } @@ -145,7 +163,7 @@ export async function dispatchClaudeTurn( if (error instanceof AgentSessionPreDispatchError) { throw error } - return { state: 'rejected', ...claudeWriteFailureRejection(error) } + return { state: 'rejected', ...claudeWriteFailureRejection(session, input.sessionId, error) } } const waiter = replay.waiter if (waiter.settledUuid) { @@ -163,7 +181,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(session, input.sessionId, error) } } if (!waiter.retired) { retireWaiter(session, waiter) diff --git a/src/main/claude/claude-structured-effort-reporting.test.ts b/src/main/claude/claude-structured-effort-reporting.test.ts index 2c319c86ee72..dcee9def9add 100644 --- a/src/main/claude/claude-structured-effort-reporting.test.ts +++ b/src/main/claude/claude-structured-effort-reporting.test.ts @@ -244,7 +244,7 @@ describe('Claude effort against the model that must run it', () => { const { session } = sessionWith('high', calls, { model: 'sonnet', catalog: [SONNET] }) session.options.set('effort', 'low') - await restoreClaudeStructuredSessionOptions(session, undefined) + await restoreClaudeStructuredSessionOptions(session, undefined, 'session-1') expect(session.options.get('effort')).toBe('low') expect(session.restoreSkippedOptions.has('effort')).toBe(false) @@ -257,7 +257,7 @@ describe('Claude effort against the model that must run it', () => { session.options.set('model', 'haiku') session.options.set('effort', 'high') - await restoreClaudeStructuredSessionOptions(session, undefined) + await restoreClaudeStructuredSessionOptions(session, undefined, 'session-1') expect(session.options.has('effort')).toBe(false) expect(session.restoreSkippedOptions.has('effort')).toBe(true) diff --git a/src/main/claude/claude-structured-history-window.ts b/src/main/claude/claude-structured-history-window.ts index 00ae86920251..61294e67493f 100644 --- a/src/main/claude/claude-structured-history-window.ts +++ b/src/main/claude/claude-structured-history-window.ts @@ -17,6 +17,7 @@ import { join } from 'node:path' import type { AgentSessionJournalIdentity } from '../../shared/agent-session-journal-types' import { resolveSessionFilePath } from '../native-chat/session-file-resolver' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' import type { ProviderHistoryItem, ProviderHistoryWindow @@ -281,12 +282,8 @@ export async function readClaudeProviderHistoryWindow( } catch (error) { // 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, - sessionId: input.sessionId, - error - }) + // Oversize is no longer among them, so only the trace separates what is left. + traceAgentSessionError({ step: 'claude-history-window', sessionId: input.sessionId, error }) return INCONSISTENT } } diff --git a/src/main/claude/claude-structured-journal-translation-background-tasks.test.ts b/src/main/claude/claude-structured-journal-translation-background-tasks.test.ts index 312eb6d05a27..5880f7d9ba09 100644 --- a/src/main/claude/claude-structured-journal-translation-background-tasks.test.ts +++ b/src/main/claude/claude-structured-journal-translation-background-tasks.test.ts @@ -179,6 +179,7 @@ describe('claude journal translation — background task rows', () => { return appendItem(...args) }) const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedOperations: 1, maxQueuedOperations: 4, @@ -252,7 +253,7 @@ describe('claude journal translation — background task rows', () => { it('coalesces an unbound overflow patch and aliased final notification', async () => { const persisted = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const translator = createClaudeJournalTranslator({ sink: deferred.sink, fallbackIdPrefix: 'test' @@ -292,7 +293,7 @@ describe('claude journal translation — background task rows', () => { it('reconciles an aliased notification after a parentless overflow patch was persisted', async () => { const persisted = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(persistedTarget(persisted)) const first = createClaudeJournalTranslator({ sink: deferred.sink, fallbackIdPrefix: 'first' }) fillLiveTaskRows(first) @@ -353,7 +354,7 @@ describe('claude journal translation — background task rows', () => { it('resolves a queued restart identity after the sink rebinds', async () => { const persisted = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(persistedTarget(persisted)) const first = createClaudeJournalTranslator({ sink: deferred.sink, fallbackIdPrefix: 'first' }) @@ -371,7 +372,7 @@ describe('claude journal translation — background task rows', () => { first.dispose() await deferred.drained() - const restarted = createDeferredStructuredAgentSessionEventSink() + const restarted = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const second = createClaudeJournalTranslator({ sink: restarted.sink, fallbackIdPrefix: 'second' @@ -397,7 +398,7 @@ describe('claude journal translation — background task rows', () => { it('keeps pending writes from distinct runs when a translator is recreated', async () => { const persisted = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const first = createClaudeJournalTranslator({ sink: deferred.sink, fallbackIdPrefix: 'first' }) spawnToolCall(first, 'toolu-first') diff --git a/src/main/claude/claude-structured-journal-translation.test.ts b/src/main/claude/claude-structured-journal-translation.test.ts index 1b03881e471b..8ff7b87f3ec2 100644 --- a/src/main/claude/claude-structured-journal-translation.test.ts +++ b/src/main/claude/claude-structured-journal-translation.test.ts @@ -258,7 +258,7 @@ describe('Claude structured journal translation', () => { now: () => 1_700_000_000_000, mintEpoch: () => 'epoch-1' }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: vi.fn() }) let scheduled: (() => void) | null = null const translator = createClaudeJournalTranslator({ @@ -317,7 +317,7 @@ describe('Claude structured journal translation', () => { now: () => 1_700_000_000_000, mintEpoch: () => 'epoch-1' }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: vi.fn() }) const translator = createClaudeJournalTranslator({ sink: deferred.sink }) const approval = prompt({ diff --git a/src/main/claude/claude-structured-model-preflight.test.ts b/src/main/claude/claude-structured-model-preflight.test.ts index 930947e112db..31f148675687 100644 --- a/src/main/claude/claude-structured-model-preflight.test.ts +++ b/src/main/claude/claude-structured-model-preflight.test.ts @@ -63,7 +63,7 @@ describe('Claude model pre-flight against the catalog the CLI listed', () => { const { session, calls } = sessionWith([DEFAULT_ROW, SONNET]) session.options.set('model', 'claude-opus-4-retired') - await restoreClaudeStructuredSessionOptions(session, undefined) + await restoreClaudeStructuredSessionOptions(session, undefined, 'session-1') expect(calls).toEqual(['list_models']) expect(session.options.has('model')).toBe(false) @@ -123,7 +123,7 @@ describe('Claude model pre-flight against the catalog the CLI listed', () => { const { session, calls } = sessionWith([DEFAULT_ROW, SONNET]) session.options.set('model', 'sonnet') - await restoreClaudeStructuredSessionOptions(session, undefined) + await restoreClaudeStructuredSessionOptions(session, undefined, 'session-1') expect(calls).toEqual(['list_models', 'set_model:sonnet']) expect(session.options.get('model')).toBe('sonnet') diff --git a/src/main/claude/claude-structured-options-context-window.test.ts b/src/main/claude/claude-structured-options-context-window.test.ts index 452009b36895..e9a07733a896 100644 --- a/src/main/claude/claude-structured-options-context-window.test.ts +++ b/src/main/claude/claude-structured-options-context-window.test.ts @@ -66,7 +66,7 @@ describe('the context ring after a session option write', () => { const s = ringSession() s.session.options.set('model', 'opusplan') s.session.options.set('permissionMode', 'plan') - await restoreClaudeStructuredSessionOptions(s.session, undefined) + await restoreClaudeStructuredSessionOptions(s.session, undefined, 'session-1') expect(s.setModel).toHaveBeenCalledWith('opusplan', { timeoutMs: undefined }) expect(s.modelMayHaveChanged).not.toHaveBeenCalled() }) @@ -74,7 +74,7 @@ describe('the context ring after a session option write', () => { it('asks for the new window when a restore cannot put the stored model back', async () => { const s = ringSession([{ value: 'sonnet', displayName: 'Sonnet' }]) s.session.options.set('model', 'retired-model') - await restoreClaudeStructuredSessionOptions(s.session, undefined) + await restoreClaudeStructuredSessionOptions(s.session, undefined, 'session-1') expect(s.session.restoreSkippedOptions).toEqual(new Set(['model'])) expect(s.modelMayHaveChanged).toHaveBeenCalledTimes(1) }) @@ -82,7 +82,7 @@ describe('the context ring after a session option write', () => { it('sizes a new session from the model its restore applied', async () => { const s = ringSession([{ value: 'opus[1m]', displayName: 'Opus (1M)' }]) s.session.options.set('model', 'opus[1m]') - await restoreClaudeStructuredSessionOptions(s.session, undefined) + await restoreClaudeStructuredSessionOptions(s.session, undefined, 'session-1') expect(s.respond('turn-a', 1_000)).toMatchObject({ windowTokens: 1_000_000, percentage: 10 }) }) @@ -102,7 +102,7 @@ describe('the context ring after a session option write', () => { const skipped = ringSession([{ value: 'sonnet', displayName: 'Sonnet' }]) skipped.session.options.set('model', 'retired-model[1m]') - await restoreClaudeStructuredSessionOptions(skipped.session, undefined) + await restoreClaudeStructuredSessionOptions(skipped.session, undefined, 'session-1') expect(skipped.respond('turn-a', 1_000)).toBeNull() }) diff --git a/src/main/claude/claude-structured-options.test.ts b/src/main/claude/claude-structured-options.test.ts index a92149a2cddf..d52bc7b56c64 100644 --- a/src/main/claude/claude-structured-options.test.ts +++ b/src/main/claude/claude-structured-options.test.ts @@ -180,7 +180,7 @@ describe('Claude structured Fast mode', () => { const { session, applyFlagSettings } = fastModeSession(undefined) session.options.set('fastMode', 'false') - await restoreClaudeStructuredSessionOptions(session, undefined) + await restoreClaudeStructuredSessionOptions(session, undefined, 'session-1') expect(session.options.get('fastMode')).toBe('false') expect(session.restoreSkippedOptions.has('fastMode')).toBe(false) @@ -467,9 +467,16 @@ describe('Claude structured option restore under the request deadline', () => { ['effort', 'high'], ['permissionMode', 'plan'] ]) - vi.spyOn(console, 'warn').mockImplementation(() => {}) + const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) - await expect(restoreClaudeStructuredSessionOptions(session, 10)).resolves.toBeUndefined() + await expect( + restoreClaudeStructuredSessionOptions(session, 10, 'session-1') + ).resolves.toBeUndefined() + expect(warn).toHaveBeenCalledWith( + '[agent-session] claude-option-restore failed', + expect.objectContaining({ sessionId: 'session-1' }), + expect.any(ClaudeControlRequestTimeoutError) + ) expect(Object.fromEntries(session.options)).toEqual({ model: 'sonnet', effort: 'high' }) expect([...session.restoreSkippedOptions]).toEqual(['permissionMode']) diff --git a/src/main/claude/claude-structured-options.ts b/src/main/claude/claude-structured-options.ts index 2f0b7ac4b707..46f2a39ef029 100644 --- a/src/main/claude/claude-structured-options.ts +++ b/src/main/claude/claude-structured-options.ts @@ -1,6 +1,7 @@ import type { EffortLevel, PermissionMode } from '@anthropic-ai/claude-agent-sdk' import { ClaudeControlRequestError } from './claude-stream-json-connection' import { ClaudeControlRequestTimeoutError } from './claude-agent-sdk-control-requests' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' import { AgentSessionOptionRejectedError, isAgentSessionOptionRejectedError @@ -250,7 +251,8 @@ export async function setClaudeStructuredOption( export async function restoreClaudeStructuredSessionOptions( session: ClaudeSession, - timeoutMs: number | undefined + timeoutMs: number | undefined, + sessionId: string ): Promise { // Any write that was already in flight belongs to the previous acquisition // state and must not repopulate this map after restore starts. @@ -268,9 +270,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` - ) + traceAgentSessionError({ + step: 'claude-option-restore', + sessionId, + error, + detail: { option: key, providerSessionId: session.providerSessionId } + }) session.options.set(key, value) session.confirmedOptions.delete(key) continue diff --git a/src/main/claude/claude-structured-provider-fallback.test.ts b/src/main/claude/claude-structured-provider-fallback.test.ts index a3a47c8bea8a..31a27e83e785 100644 --- a/src/main/claude/claude-structured-provider-fallback.test.ts +++ b/src/main/claude/claude-structured-provider-fallback.test.ts @@ -80,7 +80,7 @@ describe('Claude provider fallback', () => { now: () => 1_700_000_000_000, mintEpoch: () => 'epoch-1' }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, diff --git a/src/main/claude/claude-structured-resume-point.test.ts b/src/main/claude/claude-structured-resume-point.test.ts index 862909a2cd66..552af80c82b7 100644 --- a/src/main/claude/claude-structured-resume-point.test.ts +++ b/src/main/claude/claude-structured-resume-point.test.ts @@ -135,8 +135,9 @@ 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) }) + '[agent-session] claude-exit-cursor-persist failed', + { sessionId: 'session-1' }, + expect.any(Error) ) }) }) diff --git a/src/main/claude/claude-structured-resume-point.ts b/src/main/claude/claude-structured-resume-point.ts index e8124f52d27d..d6ef69b4fa49 100644 --- a/src/main/claude/claude-structured-resume-point.ts +++ b/src/main/claude/claude-structured-resume-point.ts @@ -1,3 +1,4 @@ +import { traceAgentSessionError } from '../observability/agent-session-error-trace' import type { ClaudeSession, ClaudeStructuredSessionAdapterDeps @@ -6,7 +7,7 @@ import type { /** * Record a completed turn: its leaf becomes the one close and exit persist, and the durable point * advances in place so an owner that dies before its close path runs keeps it. Writes run one at a - * time, and a failure is only logged: this is bookkeeping and must never fail the turn. + * time, and a failure is only reported: this is bookkeeping and must never fail the turn. */ export function persistClaudeTurnResumePoint( sessionId: string, @@ -35,10 +36,11 @@ export function persistClaudeTurnResumePoint( }) ) .catch((error: unknown) => { - console.warn('[claude-resume-point] turn-end resume point was not persisted:', { + traceAgentSessionError({ + step: 'claude-resume-point-persist', sessionId, - leafUuid, - error + error, + detail: { leafUuid } }) // Forget the failed leaf so the next turn end retries it even when the leaf has not moved. if (session.resumePointWrite === write) { diff --git a/src/main/claude/claude-structured-session-acquisition.ts b/src/main/claude/claude-structured-session-acquisition.ts index b4adbfccfa5c..cb7accbf27d1 100644 --- a/src/main/claude/claude-structured-session-acquisition.ts +++ b/src/main/claude/claude-structured-session-acquisition.ts @@ -275,6 +275,7 @@ export async function acquireClaudeSession({ session.startup.settled = Promise.race([ session.startup.settled, settleClaudeSessionStartup({ + sessionId, session, facts: readClaudeStartupFacts({ connection, diff --git a/src/main/claude/claude-structured-session-adapter.ts b/src/main/claude/claude-structured-session-adapter.ts index 64d3c67c2277..b68d87ab46bd 100644 --- a/src/main/claude/claude-structured-session-adapter.ts +++ b/src/main/claude/claude-structured-session-adapter.ts @@ -191,7 +191,7 @@ export class ClaudeStructuredSessionAdapter implements StructuredAgentSessionAda dispatchClaudeTurn(this.session(input.sessionId), input, input.beforeDispatch) compact: NonNullable = (input) => - dispatchClaudeCommand(this.session(input.sessionId), input.command) + dispatchClaudeCommand(this.session(input.sessionId), input.command, input.sessionId) cancelTurn: StructuredAgentSessionAdapter['cancelTurn'] = (request) => cancelClaudeStructuredTurn({ diff --git a/src/main/claude/claude-structured-session-exit-lifecycle.ts b/src/main/claude/claude-structured-session-exit-lifecycle.ts index 854646490a8c..86a324891a7c 100644 --- a/src/main/claude/claude-structured-session-exit-lifecycle.ts +++ b/src/main/claude/claude-structured-session-exit-lifecycle.ts @@ -4,6 +4,7 @@ import { providerStartupFailureFact } from '../native-chat/agent-session-wire/structured-agent-session-failure-text' import { settledClaudeTurnEndLeaf } from './claude-structured-resume-point' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' import { claudeRootExitObserved, settleClaudeExitedSession @@ -79,8 +80,8 @@ export function settleClaudeUnexpectedExit( // Persist the last completed turn before publishing the lifecycle // 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 }) + // Recovery still publishes: the record keeps its last durable point, and the loss is reported. + traceAgentSessionError({ step: 'claude-exit-cursor-persist', sessionId, error }) }) if (exits.get(sessionId) !== exit) { settleClaudeExitedSession(exit.session) 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 d89bd1feb094..ca55129dec73 100644 --- a/src/main/claude/claude-structured-session-reading-control.test.ts +++ b/src/main/claude/claude-structured-session-reading-control.test.ts @@ -212,6 +212,7 @@ describe('Claude structured reading control', () => { const persisted = new Map() const target = persistedTarget(persisted) const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedOperations: 1, maxQueuedOperations: 4, diff --git a/src/main/claude/claude-structured-session-startup.ts b/src/main/claude/claude-structured-session-startup.ts index ce14a64dd2cf..d48c7802c104 100644 --- a/src/main/claude/claude-structured-session-startup.ts +++ b/src/main/claude/claude-structured-session-startup.ts @@ -163,6 +163,7 @@ function claudeStartedReportedOptions( /** Applies startup facts to the published session and restores saved options; only then does the * session take input. Any failure faults the session so the user sees why it never started. */ export async function settleClaudeSessionStartup(input: { + sessionId: string session: ClaudeSession facts: Promise isCurrent: () => boolean @@ -185,7 +186,7 @@ export async function settleClaudeSessionStartup(input: { return } applyClaudeStartupFacts(session, facts) - await restoreClaudeStructuredSessionOptions(session, input.requestTimeoutMs) + await restoreClaudeStructuredSessionOptions(session, input.requestTimeoutMs, input.sessionId) if (!superseded()) { input.onStarted({ // `list_models` is answered from this same initialize result, so nothing is re-read. 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..4b977ac31aaa 100644 --- a/src/main/claude/claude-structured-turn-resume-point.test.ts +++ b/src/main/claude/claude-structured-turn-resume-point.test.ts @@ -180,8 +180,9 @@ 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' }) + '[agent-session] claude-resume-point-persist failed', + { sessionId: 'session-1', leafUuid: 'a2' }, + expect.any(Error) ) await expect(adapter.closeSession('session-1')).resolves.toBe(true) expect(persistedHandles).toEqual([expect.objectContaining({ leafUuid: 'a2' })]) diff --git a/src/main/claude/claude-subagent-resume-after-restart.test.ts b/src/main/claude/claude-subagent-resume-after-restart.test.ts index ef6c067db9ea..72c8c812c95d 100644 --- a/src/main/claude/claude-subagent-resume-after-restart.test.ts +++ b/src/main/claude/claude-subagent-resume-after-restart.test.ts @@ -137,7 +137,7 @@ async function openJournal(): Promise { /** One provider process: a fresh sink and translator over the session's journal. */ function acquire(journal: AgentSessionJournal) { - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const translator = createClaudeJournalTranslator({ sink: deferred.sink, coalesceMs: 0 }) deferred.bind({ journal, fence: 1, publish: () => {} }) const settle = async (): Promise => { @@ -190,7 +190,7 @@ const rosterIds = (journal: AgentSessionJournal): Set => /** An older build re-rostered a resumed child in the later turn's row, so two rows list it. */ async function journalAnOlderBuildListedTwice(): Promise { const journal = await openJournal() - const older = createDeferredStructuredAgentSessionEventSink() + const older = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) older.bind({ journal, fence: 1, publish: () => {} }) const listed = (id: string, state: NativeChatSubagentEntry['state']) => ({ id, diff --git a/src/main/claude/claude-subagent-roster.test.ts b/src/main/claude/claude-subagent-roster.test.ts index 34ff506ee037..508c94543287 100644 --- a/src/main/claude/claude-subagent-roster.test.ts +++ b/src/main/claude/claude-subagent-roster.test.ts @@ -462,7 +462,7 @@ describe('ClaudeSubagentRoster — through the real sink queue', () => { }, appendTombstone: async () => ({ epoch: 'e', sequence: 0 }) } as unknown as AgentSessionJournal - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, diff --git a/src/main/codex/codex-structured-journal-goal-resume.test.ts b/src/main/codex/codex-structured-journal-goal-resume.test.ts index 6df0ba015757..d398382c5873 100644 --- a/src/main/codex/codex-structured-journal-goal-resume.test.ts +++ b/src/main/codex/codex-structured-journal-goal-resume.test.ts @@ -34,7 +34,7 @@ function goalFrame(goal: Record = {}): Record } function goalJournal( - options: Parameters[0] = {} + options: Partial[0]> = {} ) { let rowSequence = 0 let publishes = 0 @@ -43,7 +43,10 @@ function goalJournal( let visitedItems = 0 const rows = new Map() const writes: string[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink(options) + const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, + ...options + }) // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: a fake journal exposing only the members the goal translator and deferred sink call. const journal = { get epoch() { diff --git a/src/main/codex/codex-structured-journal-goal-revision.test.ts b/src/main/codex/codex-structured-journal-goal-revision.test.ts index 4f8276005770..c1f0a2457086 100644 --- a/src/main/codex/codex-structured-journal-goal-revision.test.ts +++ b/src/main/codex/codex-structured-journal-goal-revision.test.ts @@ -56,7 +56,7 @@ function goalFrame(goal: Record = {}) { /** The host's own sink bound to a real journal. Its publish is what a subscriber * receives: the page after the cursor it had caught up to. */ function journalSink(journal: AgentSessionJournal) { - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const published: AgentSessionHistoryPage[] = [] let subscriberCursor: AgentJournalCursor | null = null deferred.bind({ diff --git a/src/main/codex/codex-structured-journal-subagent-readers.test.ts b/src/main/codex/codex-structured-journal-subagent-readers.test.ts index 69e28d67ec4b..24cb698506b1 100644 --- a/src/main/codex/codex-structured-journal-subagent-readers.test.ts +++ b/src/main/codex/codex-structured-journal-subagent-readers.test.ts @@ -51,7 +51,7 @@ async function openJournal(root: string): Promise { async function session() { const root = await mkdtemp(join(tmpdir(), 'orca-codex-children-')) let journal = await openJournal(root) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: () => {} }) cleanups.push(async () => { deferred.close() diff --git a/src/main/codex/codex-structured-journal-translation-settlement.test.ts b/src/main/codex/codex-structured-journal-translation-settlement.test.ts index 344d99e03b4d..bbf1d43985bb 100644 --- a/src/main/codex/codex-structured-journal-translation-settlement.test.ts +++ b/src/main/codex/codex-structured-journal-translation-settlement.test.ts @@ -129,6 +129,7 @@ function deferredTarget( function hardWatermarkDeferred() { return createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedBytes: 1, maxQueuedBytes: 1, diff --git a/src/main/codex/codex-structured-journal-translation-turn-lifecycle.test.ts b/src/main/codex/codex-structured-journal-translation-turn-lifecycle.test.ts index f9714bbe0625..aae886444fdb 100644 --- a/src/main/codex/codex-structured-journal-translation-turn-lifecycle.test.ts +++ b/src/main/codex/codex-structured-journal-translation-turn-lifecycle.test.ts @@ -223,7 +223,7 @@ describe('codex turn lifecycle rows', () => { now: () => 9_000, stateDirectory: join(root, SESSION_ID) }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const translator = createCodexJournalTranslator({ sink: deferred.sink, sessionId: SESSION_ID, diff --git a/src/main/codex/codex-structured-journal-translation.test.ts b/src/main/codex/codex-structured-journal-translation.test.ts index 676d9054ed70..efb079284bdc 100644 --- a/src/main/codex/codex-structured-journal-translation.test.ts +++ b/src/main/codex/codex-structured-journal-translation.test.ts @@ -127,6 +127,7 @@ function deferredTarget( function hardWatermarkDeferred() { return createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedBytes: 1, maxQueuedBytes: 1, @@ -713,6 +714,7 @@ describe('codex journal translation', () => { const publishes: string[] = [] const readingControl = { pauseReading: vi.fn(), resumeReading: vi.fn() } const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedBytes: 1, maxQueuedBytes: 1, diff --git a/src/main/codex/codex-structured-journal-turn-settles-once-journal.test.ts b/src/main/codex/codex-structured-journal-turn-settles-once-journal.test.ts index 7011cfa0302f..ba03c8abd3a1 100644 --- a/src/main/codex/codex-structured-journal-turn-settles-once-journal.test.ts +++ b/src/main/codex/codex-structured-journal-turn-settles-once-journal.test.ts @@ -39,7 +39,7 @@ async function session() { stateDirectory: root, now: () => 1_000 }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: () => {} }) cleanups.push(async () => { deferred.close() 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 2c01a653af38..480692a5bedd 100644 --- a/src/main/native-chat/agent-session-journal/journal-database.ts +++ b/src/main/native-chat/agent-session-journal/journal-database.ts @@ -9,6 +9,7 @@ import { hardenSqliteDatabaseFiles } from '../../sqlite/harden-database-files' import { createJournalTablesSql, JOURNAL_DB_SCHEMA_VERSION } from './journal-database-schema' import { JournalUnreleasedSchemaError } from './journal-open-failure' import { ensureQueuedMessagesTable } from './queued-message-schema' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export const JOURNAL_BUSY_TIMEOUT_MS = 5000 /** Bounds the WAL a checkpoint leaves behind; SQLite truncates it back to this after a reset. */ @@ -120,10 +121,7 @@ export function runJournalTransaction( try { db.exec('ROLLBACK') } catch (rollbackError) { - console.warn( - '[agent-session-journal] rolling back a failed transaction failed', - rollbackError - ) + traceAgentSessionError({ step: 'journal-rollback', error: rollbackError }) onStranded() } } diff --git a/src/main/native-chat/agent-session-journal/journal-open-failure.ts b/src/main/native-chat/agent-session-journal/journal-open-failure.ts index 5e014c279cb1..b8ee7a2041f0 100644 --- a/src/main/native-chat/agent-session-journal/journal-open-failure.ts +++ b/src/main/native-chat/agent-session-journal/journal-open-failure.ts @@ -13,6 +13,7 @@ import { } from '../../../shared/agent-session-wire-refusals' import { isSqliteCorruption } from '../../sqlite/sqlite-read-failure' import { AgentSessionJournalError } from './journal-write-guards' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' type JournalRefusalReason = AgentSessionRefusalReason<'agent_session_journal_unreadable'> @@ -111,7 +112,7 @@ export function journalOpenReadRefusal(error: unknown): AgentSessionRefusalError if (isAgentSessionRefusalError(error)) { return error } - return unreadableRefusal(error, journalRefusalReason(error), true) + return unreadableRefusal(error, journalRefusalReason(error), { log: true }) } const MAX_LOGGED_SESSIONS = 256 @@ -134,7 +135,7 @@ export function createJournalOpenReadRefusals() { if (!repeat && (logged.has(sessionId) || logged.size < MAX_LOGGED_SESSIONS)) { logged.set(sessionId, failure) } - return unreadableRefusal(error, reason, !repeat) + return unreadableRefusal(error, reason, { log: !repeat, sessionId }) }, /** The session opened or closed: its next failure is news. */ forget: (sessionId: string): void => { @@ -146,10 +147,15 @@ export function createJournalOpenReadRefusals() { function unreadableRefusal( error: unknown, reason: JournalRefusalReason, - log: boolean + report: { log: boolean; sessionId?: string } ): AgentSessionRefusalError { - if (log) { - console.warn('[agent-session] opening the conversation for a read failed:', error) + if (report.log) { + traceAgentSessionError({ + step: 'journal-open-read', + ...(report.sessionId === undefined ? {} : { sessionId: report.sessionId }), + error, + detail: { reason } + }) } const code = 'agent_session_journal_unreadable' return new AgentSessionRefusalError(refuse(code, { reason }, code), { cause: error }) 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 ea28ba4ef838..131457c94684 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 @@ -380,7 +380,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 warnings = vi.spyOn(console, 'warn').mockImplementation(() => undefined) const input = { database, identity: IDENTITY, @@ -402,7 +402,12 @@ describe('importing a per-chat journal', () => { ).toMatchObject({ total: 0 }) - expect(errors).toHaveBeenCalledOnce() + // Refused on every open, logged once. + expect( + warnings.mock.calls.filter( + ([line]) => line === '[agent-session] legacy-journal-import failed' + ) + ).toHaveLength(1) // 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 warnings = vi.spyOn(console, 'warn').mockImplementation(() => undefined) const input = { database, identity: IDENTITY, @@ -431,7 +436,12 @@ describe('importing a per-chat journal', () => { expect((await readFile(legacyJournalDatabaseFile(legacyDir()))).equals(before)).toBe(true) expect(readJournalSessionEpoch(database.db, IDENTITY.sessionId)).toBeNull() - expect(errors).toHaveBeenCalledOnce() + // Refused on every open, logged once. + expect( + warnings.mock.calls.filter( + ([line]) => line === '[agent-session] legacy-journal-import failed' + ) + ).toHaveLength(1) }) // T-R2B1: the copy committed and only the delete failed (a crash between them is the same). Rows appended since, a restart, and a 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..9ac2c52b227a 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 @@ -54,6 +54,7 @@ import { readJournalRowsAfter, readJournalSessionEpoch } from './journal-row-table' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' const INSERT_ROW = 'INSERT INTO journal_rows (session_id, epoch, seq, ts, row_json) VALUES (?, ?, ?, ?, ?)' @@ -130,7 +131,7 @@ async function importOnce(input: ImportInput): Promise void = (path) => rmSync(path, { force: true }) ): void { const file = legacyJournalDatabaseFile(legacyDirectory) @@ -133,7 +135,7 @@ export function retireLegacyJournal( remove(path) } } catch (error) { - console.warn(`[agent-session-journal] deleting imported ${legacyDirectory} failed`, error) + traceAgentSessionError({ step: 'legacy-journal-retire', sessionId, 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 96b45c9d17cb..325e56efce91 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 @@ -43,6 +43,7 @@ import { settleQueuedMessagesForRow } from './queued-message-settlement' import { AgentSessionJournalError, assertJournalWritable } from './journal-write-guards' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** Tombstones must outlive the window in which their operation id could still be admitted as new. */ export const QUEUED_MESSAGE_REPLAY_WINDOW_MS = @@ -305,12 +306,9 @@ export class JournalQueuedMessages { /** Bookkeeping at open: a failure is reported and retried at the next open, * never allowed to fail opening the chat. */ repairAndPruneAtOpen(): Promise { - return this.repairAndPrune().catch((error: unknown) => { - console.warn('[journal-open] queued-message repair skipped:', { - sessionId: this.deps.sessionId, - error: error instanceof Error ? error.message : String(error) - }) - }) + return this.repairAndPrune().catch((error: unknown) => + traceAgentSessionError({ step: 'queued-repair', sessionId: this.deps.sessionId, error }) + ) } /** 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..39ad16ae8a8d 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 @@ -23,6 +23,7 @@ import { import { isQueuedAgentJournalSubmission } from '../../../shared/agent-session-queued-submission' import type { AgentSessionJournal } from './journal-store' import { reconcileSubmissions, type ProviderHistoryWindow } from './journal-submission-reconciler' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** * Only a text-only body can be compared against provider content. A submission @@ -101,10 +102,11 @@ 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:', { - clientMessageId: outcome.clientMessageId, - reason: outcome.reason, - fence: input.fence + traceAgentSessionError({ + step: 'restart-reconciliation', + sessionId: input.journal.snapshot().sessionId, + error: `submission left unconfirmed: ${outcome.reason}`, + detail: { clientMessageId: outcome.clientMessageId, fence: input.fence } }) continue } 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..9dc4d704ec3e 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 @@ -4,6 +4,7 @@ import type { JournalHostDatabase } from './journal-host-database' import type { AgentJournalCursor } from '../../../shared/agent-session-journal-types' import type { JournalRow } from './journal-row-schema' import { assertJournalFence, assertJournalWritable } from './journal-write-guards' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** Runs between BEGIN IMMEDIATE and COMMIT, on the SAME connection as the row * insert; a throw rolls the whole append back. Synchronous by construction so @@ -83,10 +84,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:', { + traceAgentSessionError({ + step: 'journal-row-bookkeeping', sessionId: this.deps.sessionId, - kind: row.kind, - error: error instanceof Error ? error.message : String(error) + error, + detail: { kind: row.kind } }) } } 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..b55eeae7c902 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 @@ -107,8 +107,9 @@ 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' }) + '[agent-session] journal-row-bookkeeping failed', + expect.objectContaining({ kind: 'dispatch' }), + expect.any(Error) ) 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 0e42a22be4d9..0a6494c05b08 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 @@ -509,8 +509,9 @@ describe('open-time repair and retention', () => { try { const journal = await open() expect(warn).toHaveBeenCalledWith( - '[journal-open] queued-message repair skipped:', - expect.objectContaining({ error: 'SQLITE_FULL' }) + '[agent-session] queued-repair failed', + expect.anything(), + expect.objectContaining({ message: '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-agent-start.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-agent-start.ts index a4c93fa00f88..f61107eb1b1d 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-agent-start.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-agent-start.ts @@ -32,6 +32,7 @@ import { structuredAgentSessionResumeOperationId, structuredAgentSessionResumeParams } from './structured-agent-session-resume-eligibility' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** A resume answers with the attach's own refusal, verdict and all, so the asker can tell a lease * someone else is settling from an owner that will not come back. */ @@ -79,7 +80,7 @@ export function ensureStructuredAgentSessionAgentForOperation( ): Promise { return ensureStructuredAgentSessionAgent(context, sessionId).catch((error: unknown) => { // The error is Orca's own and goes to the log; the refusal says only that the start failed. - console.warn('[agent-session] starting the agent for an operation failed:', error) + traceAgentSessionError({ step: 'operation-agent-start', sessionId, error }) return { ok: false, refusal: refuseUnclassified( diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-attach-flow.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-attach-flow.ts index c469035c4689..09ff455b27d5 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-attach-flow.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-attach-flow.ts @@ -44,6 +44,7 @@ import { } from '../../observability/agent-session-instrumentation' import type { ProviderHistoryWindow } from '../agent-session-journal/journal-submission-reconciler' import type { AgentSessionJournal } from '../agent-session-journal/journal-store' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type AttachFlowInput = { store: AgentSessionRecordStore @@ -206,7 +207,7 @@ export async function performAttach( const thrown = failed ? error : preSpawnFailureInWords(error, wording) if (failed || thrown !== error) { // The answer carries only its sentence, so what failed is kept here. - console.warn('[agent-session] provider start failed:', error) + traceAgentSessionError({ step: 'provider-start', sessionId, error }) } return ( failed ?? { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-root-exit.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-root-exit.test.ts index 7cfd7fe86234..c16ab2d587e5 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-claude-root-exit.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-claude-root-exit.test.ts @@ -122,7 +122,7 @@ describe('Claude root-exit stop', () => { journalDatabase: openTestJournalHostDatabase(root), claimKeyId: 'key-1' } - const runtimeState = new StructuredAgentSessionHostRuntimeState(deps) + const runtimeState = new StructuredAgentSessionHostRuntimeState(deps, () => {}) claude.connections[0]!.handlers.onExit?.(new Error('provider exited')) await expect( diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-close.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-close.test.ts index bf3cd1f96a60..070b8cfe062f 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-close.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-close.test.ts @@ -21,6 +21,11 @@ import { } from './structured-agent-session-rest-test-rig' import { StructuredAgentSessionIdleSweep } from './structured-agent-session-idle-sweep' import { hostTestAttachParams } from './structured-agent-session-host-test-data' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) let rig: RestTestRig @@ -315,12 +320,11 @@ describe('the wind-down retry with a message queued (P2-31)', () => { hasOpenDispatch: () => false, stopAgent, stopStartingAgent: stopAgent, - closeConversation: vi.fn(async () => false), - onError: (_id, error) => { - throw error - } + closeConversation: vi.fn(async () => false) }) + vi.mocked(traceAgentSessionError).mockClear() await sweep.tick() + expect(traceAgentSessionError).not.toHaveBeenCalled() expect(stopAgent).not.toHaveBeenCalled() }) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-lifetime.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-lifetime.ts index f69129183b4a..e089aa10da67 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-lifetime.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-lifetime.ts @@ -82,7 +82,6 @@ export function createStructuredAgentSessionConversationLifetime(host: { cause: 'host-stop' }), closeConversation, - onError: (sessionId, error) => deps().onEventSinkError?.({ sessionId, error }), ...deps().idleSweep }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-open.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-open.ts index ec938f17f13b..419c43c7b11e 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-open.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-conversation-open.ts @@ -23,10 +23,8 @@ import type { AgentSessionRecordStore } from '../../runtime/agent-session-record import type { StructuredAgentSessionAdapter } from './structured-agent-session-adapter' import { settleStaleStructuredAgentSessionState } from './structured-agent-session-dead-generation-settlement' import { structuredAgentSessionFailureWordsContext } from './structured-agent-session-send-preparation' -import type { - StructuredAgentSessionHostDeps, - StructuredAgentSessionHostSession -} from './structured-agent-session-host-types' +import type { StructuredAgentSessionHostSession } from './structured-agent-session-host-types' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type OpenedStructuredAgentSessionConversation = { session: StructuredAgentSessionHostSession @@ -38,7 +36,6 @@ export type StructuredAgentSessionConversationOpenDeps = { store: Pick adapter: Pick journalDatabase: JournalHostDatabase - onEventSinkError?: StructuredAgentSessionHostDeps['onEventSinkError'] } /** An acquisition's own open: its reserve cleared the record's death evidence, so it settles @@ -104,13 +101,13 @@ export async function openStructuredAgentSessionConversationJournal( // one is only doubt, which provider history decides under a won lease. await opened.journal.markPendingSubmissionsUnknown(fence) } catch (error) { - deps.onEventSinkError?.({ sessionId, error }) + traceAgentSessionError({ step: 'journal-open-pending-doubt', sessionId, error }) } // No child in this process writes to a journal nobody had open, so whatever it shows running // belongs to a generation that is gone, whatever the lease still claims. Settled before any // reader or child sees it. if (!options.acquisition) { - await settleGoneGeneration(deps, record, opened.journal) + await settleGoneGeneration(record, opened.journal) } return { session: { journal: opened.journal, params, child: null }, @@ -130,12 +127,11 @@ export async function resettleOpenStructuredAgentSessionConversation( ): Promise { const record = deps.store.getRecord(sessionId) if (session && record?.lease.deathEvidence) { - await settleGoneGeneration(deps, record, session.journal) + await settleGoneGeneration(record, session.journal) } } async function settleGoneGeneration( - deps: Pick, record: AgentSessionRecord, journal: AgentSessionJournal ): Promise { @@ -150,7 +146,11 @@ async function settleGoneGeneration( }) } catch (error) { // Best effort: the next open or acquire re-derives it. - deps.onEventSinkError?.({ sessionId: record.sessionId, error }) + traceAgentSessionError({ + step: 'gone-generation-settlement', + sessionId: record.sessionId, + error + }) } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.test.ts index 3557594b7513..ef787111ec43 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.test.ts @@ -9,6 +9,11 @@ import { createTrackedJournalOpener } from '../agent-session-journal/journal-hos import { StructuredAgentSessionConversations } from './structured-agent-session-conversations' import type { StructuredAgentSessionHostSession } from './structured-agent-session-host-types' import { hostTestAttachParams } from './structured-agent-session-host-test-data' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const IDENTITY: AgentSessionJournalIdentity = { sessionId: 'session-1', @@ -22,6 +27,7 @@ const journals = createTrackedJournalOpener() let root: string | null = null afterEach(async () => { + vi.mocked(traceAgentSessionError).mockClear() await journals.closeAll() if (root) { await rm(root, { recursive: true, force: true }) @@ -55,7 +61,6 @@ describe('a conversation delivers what its journal commits', () => { const deliver = vi.fn() const conversations = new StructuredAgentSessionConversations({ deliver, - onDeliveryError: vi.fn(), now: () => 0 }) const journal = await openJournal('a') @@ -74,7 +79,6 @@ describe('a conversation delivers what its journal commits', () => { const sessions: Map = new StructuredAgentSessionConversations({ deliver, - onDeliveryError: vi.fn(), now: () => 0 }) const journal = await openJournal('a') @@ -89,7 +93,6 @@ describe('a conversation delivers what its journal commits', () => { const deliver = vi.fn() const conversations = new StructuredAgentSessionConversations({ deliver, - onDeliveryError: vi.fn(), now: () => 0 }) const journal = await openJournal('a') @@ -104,7 +107,6 @@ describe('a conversation delivers what its journal commits', () => { const deliver = vi.fn() const conversations = new StructuredAgentSessionConversations({ deliver, - onDeliveryError: vi.fn(), now: () => 0 }) const replaced = await openJournal('a') @@ -123,7 +125,6 @@ describe('a conversation delivers what its journal commits', () => { const deliver = vi.fn() const conversations = new StructuredAgentSessionConversations({ deliver, - onDeliveryError: vi.fn(), now: () => 0 }) const journal = await openJournal('a') @@ -137,12 +138,10 @@ describe('a conversation delivers what its journal commits', () => { it('reports a reader failure without failing the durable write', async () => { const failure = new Error('reader failed') - const onDeliveryError = vi.fn() const conversations = new StructuredAgentSessionConversations({ deliver: () => { throw failure }, - onDeliveryError, now: () => 0 }) const journal = await openJournal('a') @@ -152,7 +151,11 @@ describe('a conversation delivers what its journal commits', () => { itemId: expect.any(String) }) - expect(onDeliveryError).toHaveBeenCalledExactlyOnceWith('session-1', failure) + expect(traceAgentSessionError).toHaveBeenCalledExactlyOnceWith({ + step: 'journal-delivery', + sessionId: 'session-1', + error: failure + }) expect(journal.snapshot().items.map((item) => item.body)).toContainEqual({ kind: 'status', text: 'durable' diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.ts index c312d6013fd5..c28d8533998b 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-conversations.ts @@ -1,5 +1,6 @@ import type { AgentSessionJournal } from '../agent-session-journal/journal-store' import type { StructuredAgentSessionHostSession } from './structured-agent-session-host-types' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** * The host's open conversations. A journal handle becomes a conversation's when it is set here, @@ -21,7 +22,6 @@ export class StructuredAgentSessionConversations extends Map< constructor( private readonly delivery: { deliver: (sessionId: string, journal: AgentSessionJournal) => void - onDeliveryError: (sessionId: string, error: unknown) => void /** A conversation became held: state that waited on it (queued drafts) re-derives. */ onOpened?: (sessionId: string) => void now: () => number @@ -46,7 +46,7 @@ export class StructuredAgentSessionConversations extends Map< try { this.delivery.deliver(sessionId, journal) } catch (error) { - this.delivery.onDeliveryError(sessionId, error) + traceAgentSessionError({ step: 'journal-delivery', sessionId, error }) } }) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-crash-turn-end.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-crash-turn-end.test.ts index c7f8f09631a2..624c284b46eb 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-crash-turn-end.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-crash-turn-end.test.ts @@ -41,6 +41,11 @@ import { HOST_TEST_LOCATION as LOCATION, HOST_TEST_SESSION as SESSION } from './structured-agent-session-host-test-data' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const PROVIDER_SESSION = 'provider-session-alpha-1' /** The tool call's row: the last thing the provider wrote before the crash. */ @@ -406,11 +411,10 @@ describe('a turn a read reached before the reconcile proved its owner dead', () it('stays unverifiable when the revision cannot be written, and a later open revises it', async () => { let now = RELAUNCHED_AT - const onEventSinkError = vi.fn() + vi.mocked(traceAgentSessionError).mockClear() openHost({ probeOwner: async () => ({ outcome: 'pid-absent' }), - now: () => now, - onEventSinkError + now: () => now }) await host.history({ sessionId: SESSION, direction: 'tail' }) const { journal } = host.collaboratorsForTests().sessions.get(SESSION)! @@ -419,7 +423,9 @@ describe('a turn a read reached before the reconcile proved its owner dead', () await host.reconcileRestartLeases() await drainSession() - expect(onEventSinkError).toHaveBeenCalledOnce() + expect(traceAgentSessionError).toHaveBeenCalledExactlyOnceWith( + expect.objectContaining({ step: 'gone-generation-settlement', sessionId: SESSION }) + ) expect(await settledTurn()).toEqual(UNVERIFIABLE_TURN) // The proof is durable on the record, so the next open converges. now += STRUCTURED_AGENT_SESSION_IDLE_MS + 1 diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.test.ts index 6677a50b4470..b39790e6b2af 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.test.ts @@ -100,7 +100,7 @@ describe('dead structured-session generation settlement', () => { verdict: { state: 'unverifiable' }, showUnexpectedExitOutcome: false }) - ).resolves.toBe(true) + ).resolves.toEqual({ ok: true }) const snapshot = journal.snapshot() expect(snapshot.submissions).toEqual([ @@ -135,9 +135,9 @@ describe('dead structured-session generation settlement', () => { showUnexpectedExitOutcome: true } - await expect(settleStructuredAgentSessionDeadGeneration(input)).resolves.toBe(true) + await expect(settleStructuredAgentSessionDeadGeneration(input)).resolves.toEqual({ ok: true }) const settledCursor = journal.cursor() - await expect(settleStructuredAgentSessionDeadGeneration(input)).resolves.toBe(true) + await expect(settleStructuredAgentSessionDeadGeneration(input)).resolves.toEqual({ ok: true }) expect(journal.cursor()).toEqual(settledCursor) expect( @@ -166,7 +166,7 @@ describe('dead structured-session generation settlement', () => { detail: providerDiagnostic('stack frame '.repeat(4_000), 'log') }) }) - ).resolves.toBe(true) + ).resolves.toEqual({ ok: true }) const statuses = journal .snapshot() @@ -258,7 +258,7 @@ describe('dead structured-session generation settlement', () => { verdict: { state: 'interrupted', completedAt: 1_000 }, showUnexpectedExitOutcome: false }) - ).resolves.toBe(true) + ).resolves.toEqual({ ok: true }) }) it('settles a live unknown submission even when no unfinished item remains', async () => { @@ -285,7 +285,7 @@ describe('dead structured-session generation settlement', () => { verdict: { state: 'interrupted', completedAt: 1_000 }, showUnexpectedExitOutcome: false }) - ).resolves.toBe(true) + ).resolves.toEqual({ ok: true }) expect(journal.submissions()).toEqual([ expect.objectContaining({ @@ -463,7 +463,7 @@ describe('whether a dead generation interrupted anything', () => { 1_000 ) }) - ).resolves.toBe(true) + ).resolves.toEqual({ ok: true }) const snapshot = journal.snapshot() expect(snapshot.items.some((item) => item.body.kind === 'status')).toBe(false) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.ts index 72caac40844d..b500f27cbf7f 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-dead-generation-settlement.ts @@ -35,6 +35,7 @@ import { exitedRootTurnScope, runningRootTurnScope } from './structured-agent-session-exit-turn-scope' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** Bounds the exit reason the lease keeps as log evidence; a provider diagnostic is held to the * same cap. */ @@ -102,6 +103,11 @@ export function unfinishedStructuredAgentSessionWorkWasInterrupted( return outcomeItems.some((item) => !isCleanlySettled(currentItems.get(item.itemId))) } +/** A failed settlement carries its error so a caller that throws can name the cause. */ +export type StructuredAgentSessionDeadGenerationSettlement = + | { ok: true } + | { ok: false; error: unknown } + export async function settleStructuredAgentSessionDeadGeneration(input: { journal: DeadGenerationJournal sessionId: string @@ -117,13 +123,12 @@ export async function settleStructuredAgentSessionDeadGeneration(input: { /** The provider never finished starting: the start that failed, keyed by the child's * generation. Its row is the one the delivery loop writes for the same start. */ exitedDuringStartup?: { generation: string | null } - onError?: (sessionId: string, error: unknown) => void -}): Promise { +}): Promise { try { const hasUnfinishedWork = hasUnfinishedStructuredAgentSessionWork(input.journal) const showUnexpectedExitOutcome = input.showUnexpectedExitOutcome ?? hasUnfinishedWork if (!showUnexpectedExitOutcome && !hasUnfinishedWork) { - return true + return { ok: true } } // A queued message is the delivery loop's to settle: it was never handed to this child. A // child that never proved its start accepted nothing either — input is written only after it @@ -189,10 +194,14 @@ export async function settleStructuredAgentSessionDeadGeneration(input: { mutations: chunk.mutations }) } - return true + return { ok: true } } catch (error) { - input.onError?.(input.sessionId, error) - return false + traceAgentSessionError({ + step: 'dead-generation-settlement', + sessionId: input.sessionId, + error + }) + return { ok: false, error } } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-delivery-loop.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-delivery-loop.ts index 373e2ae3c36e..43f400446a70 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-delivery-loop.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-delivery-loop.ts @@ -38,6 +38,7 @@ import { import { failedProviderChildStart } from './structured-agent-session-provider-child' import { handOverSubmission } from './structured-agent-session-turns' import { structuredAgentSessionCommandRunning } from './structured-agent-session-command-turn' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionDeliveryLoopDeps = { sessions: ReadonlyMap @@ -55,7 +56,6 @@ export type StructuredAgentSessionDeliveryLoopDeps = { conversationFence: (sessionId: string) => number /** Who the chat's failure sentences name. */ failureTextContext: (sessionId: string) => AgentSessionFailureWordsContext - onError: (sessionId: string, error: unknown) => void record: (sessionId: string) => AgentSessionRecord | null flushStreamedEvents: (sessionId: string) => Promise now: () => number @@ -125,14 +125,18 @@ export class StructuredAgentSessionDeliveryLoop { } } catch (error) { // The error is Orca's own and goes to the log; the chat says only that Orca failed. - this.deps.onError(sessionId, error) + traceAgentSessionError({ step: 'delivery-loop', sessionId, error }) const cause = { hostFault: true } as const await this.deps .serialize(sessionId, () => this.fail(sessionId, { startKey: null, cause })) .catch((failure: unknown) => { // Rows left queued are rejected by the next open, or by the next loop an accept wakes. this.running.delete(sessionId) - this.deps.onError(sessionId, failure) + traceAgentSessionError({ + step: 'delivery-loop-failure-settlement', + sessionId, + error: failure + }) }) } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-event-recovery.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-event-recovery.ts index f7a50627370e..fdd17395704b 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-event-recovery.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-event-recovery.ts @@ -10,6 +10,7 @@ import type { import type { StructuredAgentSessionSinkBarrier } from './structured-agent-session-event-sink' import { settleStructuredAgentSessionProviderStarted } from './structured-agent-session-provider-started' import { settleUnexpectedStructuredAgentSessionExit } from './structured-agent-session-unexpected-exit' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export class StructuredAgentSessionEventRecovery { private readonly sinkFailures = new Set() @@ -24,7 +25,6 @@ export class StructuredAgentSessionEventRecovery { publishStatus?: (sessionId: string) => void serialize: (sessionId: string, task: () => Promise) => Promise now: () => number - onBarrierError: (sessionId: string, error: unknown) => void } ) {} @@ -58,7 +58,9 @@ export class StructuredAgentSessionEventRecovery { } as const }) .then((event) => (event ? this.handle(event) : undefined)) - .catch((recoveryError) => this.context.onBarrierError(sessionId, recoveryError)) + .catch((error: unknown) => + traceAgentSessionError({ step: 'sink-failure-recovery', sessionId, error }) + ) .finally(() => this.sinkFailures.delete(sessionId)) } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink-queue.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink-queue.ts index 2d0766a4bce8..cea1e5f8edaa 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink-queue.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink-queue.ts @@ -45,7 +45,7 @@ export class StructuredAgentSessionSinkQueue { constructor( private readonly deps: { watermarks: StructuredAgentSessionSinkWatermarks - onError?: (error: unknown) => void + onFailure: (error: unknown) => void readingControl?: StructuredAgentSessionReadingControl onBackpressureChange?: ( backpressured: boolean, @@ -212,7 +212,7 @@ export class StructuredAgentSessionSinkQueue { private fail = (error: unknown): void => { if (this.failure === null) { this.failure = { error } - this.deps.onError?.(error) + this.deps.onFailure(error) } this.queue.length = 0 this.queuedBytes = 0 diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.test.ts index 46dc8fbf7e44..7a8a1cfb2bbd 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.test.ts @@ -91,7 +91,7 @@ function target( describe('deferred structured agent-session event sink', () => { it('buffers writes made before the journal exists and drains them in arrival order', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.sink.appendItem(identity(0), BODY, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) deferred.sink.appendItem(identity(1), BODY, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) @@ -110,7 +110,7 @@ describe('deferred structured agent-session event sink', () => { it('writes at the fence bound at submission time, so a rebind cannot backdate a write', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(target(1, log)) deferred.sink.appendItem(identity(0), BODY, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) @@ -127,7 +127,7 @@ describe('deferred structured agent-session event sink', () => { it('buffers replacement-acquisition events while unbound', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(target(1, log)) deferred.unbind() @@ -141,7 +141,7 @@ describe('deferred structured agent-session event sink', () => { it('resolves a lifecycle transition after journal bind and skips an existing state', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) expect( deferred.sink.tryAppendLifecycleTransition?.(identity(0), BODY, () => identity(1), { @@ -166,7 +166,7 @@ describe('deferred structured agent-session event sink', () => { it('drops buffered and later writes once closed, and refuses to rebind', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.sink.appendItem(identity(0), BODY, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) deferred.close() @@ -182,7 +182,7 @@ describe('deferred structured agent-session event sink', () => { const errors: unknown[] = [] const readingControl = { pauseReading: vi.fn(), resumeReading: vi.fn() } const deferred = createDeferredStructuredAgentSessionEventSink({ - onError: (error) => errors.push(error), + onFailure: (error) => errors.push(error), readingControl }) deferred.bind(target(4, log, 0)) @@ -206,7 +206,8 @@ describe('deferred structured agent-session event sink', () => { }) it('replaces a failed cached sink before recovery drain', async () => { - const runtime = new StructuredAgentSessionHostRuntimeState({ store: {} } as never) + // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: only the runtime state's event sinks run here; the store is never read. + const runtime = new StructuredAgentSessionHostRuntimeState({ store: {} } as never, () => {}) const failed = runtime.eventSinkFor('session-1') failed.bind(target(1, [], 0)) failed.sink.appendItem(identity(0), BODY, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) @@ -226,6 +227,7 @@ describe('deferred structured agent-session event sink', () => { const changes: boolean[] = [] const readingControl = { pauseReading: vi.fn(), resumeReading: vi.fn() } const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { maxQueuedBytes: 1_000_000, lowQueuedBytes: 0, @@ -262,6 +264,7 @@ describe('deferred structured agent-session event sink', () => { it('admits a resolved append and publication as one bounded operation', async () => { const log: Recorded[] = [] const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedOperations: 1, maxQueuedOperations: 2, @@ -299,6 +302,7 @@ describe('deferred structured agent-session event sink', () => { const changes: boolean[] = [] const readingControl = { pauseReading: vi.fn(), resumeReading: vi.fn() } const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedBytes: 1, maxQueuedBytes: 1_000_000, @@ -329,7 +333,7 @@ describe('deferred structured agent-session event sink', () => { const log: Recorded[] = [] const errors: unknown[] = [] const deferred = createDeferredStructuredAgentSessionEventSink({ - onError: (error) => errors.push(error), + onFailure: (error) => errors.push(error), watermarks: { pauseQueuedBytes: 1, maxQueuedBytes: 1, @@ -364,6 +368,7 @@ describe('deferred structured agent-session event sink', () => { const firstControl = { pauseReading: vi.fn(), resumeReading: vi.fn() } const secondControl = { pauseReading: vi.fn(), resumeReading: vi.fn() } const deferred = createDeferredStructuredAgentSessionEventSink({ + onFailure: () => {}, watermarks: { pauseQueuedBytes: 1, maxQueuedBytes: 1_000_000, @@ -395,7 +400,7 @@ describe('deferred structured agent-session event sink', () => { it('replaces a queued same-item checkpoint before it runs', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const options = { coalescingKey: 'checkpoint:item-1', turnScope: AGENT_JOURNAL_THREAD_SCOPE } deferred.sink.appendItem(identity(0), BODY, options) @@ -411,7 +416,7 @@ describe('deferred structured agent-session event sink', () => { // The journal applies a settlement id once and skips any later batch with it, // so the queue must not let a later batch replace one it has not run yet. const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const batch = (ordinal: number) => [ { kind: 'item' as const, @@ -440,7 +445,7 @@ describe('deferred structured agent-session event sink', () => { it('keeps a replacement checkpoint after distinct intervening operations', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const options = { coalescingKey: 'checkpoint:item-1', turnScope: AGENT_JOURNAL_THREAD_SCOPE } deferred.sink.appendItem(identity(0), BODY, options) @@ -457,7 +462,7 @@ describe('deferred structured agent-session event sink', () => { it('coalesces provider activity as a publication without a journal write', async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.sink.setActivity?.({ turnId: 'turn-1', text: 'Thinking' }) deferred.sink.setActivity?.({ turnId: 'turn-1', text: 'Checking the result' }) @@ -486,7 +491,7 @@ describe('producer linkage reaches the journal through every append path', () => it('forwards the whole bundle on the plain and try append paths', async () => { for (const append of ['appendItem', 'tryAppendItem'] as const) { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(target(5, log)) deferred.sink[append]?.(identity(1), BODY, { ...LINKAGE, @@ -510,7 +515,7 @@ describe('producer linkage reaches the journal through every append path', () => 'tryAppendLifecycleTransition' ] as const) { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(target(5, log)) deferred.sink[append]?.(identity(1), BODY, () => identity(1), { ...LINKAGE, @@ -530,7 +535,7 @@ describe('producer linkage reaches the journal through every append path', () => // would stamp whoever opened the batch onto all of them. Both callers are // single-producer today; a mixed batch would have to stamp per mutation. const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(target(5, log)) deferred.sink.appendLifecycleBatch?.( 'settle-1', @@ -547,7 +552,7 @@ describe('producer linkage reaches the journal through every append path', () => it("writes no linkage keys at all for the session's own agent", async () => { const log: Recorded[] = [] - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind(target(5, log)) deferred.sink.appendItem(identity(1), BODY, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) await deferred.drained() diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.ts index 121fb865db4a..179645c562de 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-event-sink.ts @@ -193,18 +193,17 @@ const DEFAULT_WATERMARKS: StructuredAgentSessionSinkWatermarks = { maxLifecycleQueuedOperations: 1_024 } -export function createDeferredStructuredAgentSessionEventSink( - deps: { - onError?: (error: unknown) => void - watermarks?: Partial - readingControl?: StructuredAgentSessionReadingControl - onBackpressureChange?: (backpressured: boolean, state: StructuredAgentSessionSinkState) => void - } = {} -): DeferredStructuredAgentSessionEventSink { +export function createDeferredStructuredAgentSessionEventSink(deps: { + /** The sink failed for good, or refused a lifecycle batch: what the provider writes is lost. */ + onFailure: (error: unknown) => void + watermarks?: Partial + readingControl?: StructuredAgentSessionReadingControl + onBackpressureChange?: (backpressured: boolean, state: StructuredAgentSessionSinkState) => void +}): DeferredStructuredAgentSessionEventSink { const watermarks = { ...DEFAULT_WATERMARKS, ...deps.watermarks } const queue = new StructuredAgentSessionSinkQueue({ watermarks, - ...(deps.onError ? { onError: deps.onError } : {}), + onFailure: deps.onFailure, ...(deps.readingControl ? { readingControl: deps.readingControl } : {}), ...(deps.onBackpressureChange ? { onBackpressureChange: deps.onBackpressureChange } : {}) }) @@ -280,7 +279,7 @@ export function createDeferredStructuredAgentSessionEventSink( appendLifecycleBatch: (settlementId, mutations, options = {}) => { const admission = appendLifecycleBatch(settlementId, mutations, options) if (!admission.accepted) { - deps.onError?.( + deps.onFailure( new Error( `lifecycle journal batch ${settlementId} rejected by sink ${admission.reason}` ) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.test.ts index 8fc810de2a4d..42b844722c71 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.test.ts @@ -44,10 +44,14 @@ function context(): StructuredAgentSessionEvictionContext & { order: string[] } } function runtimeState(): StructuredAgentSessionHostRuntimeState { - return new StructuredAgentSessionHostRuntimeState({ - store: {} as never, - adapter: {} as never - } as never) + return new StructuredAgentSessionHostRuntimeState( + // oxlint-disable-next-line typescript/consistent-type-assertions -- SAFETY: these tests use only the runtime state's event sinks; the store and adapter are never read. + { + store: {} as never, + adapter: {} as never + } as never, + () => {} + ) } describe('structured agent session eviction', () => { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.ts index 226781117bdf..37c6e9557d72 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-eviction.ts @@ -24,6 +24,7 @@ import { import type { DeferredStructuredAgentSessionEventSink } from './structured-agent-session-event-sink' import type { StructuredAgentSessionStopVerdict } from './structured-agent-session-host-types' import { withTimeout } from '../../../shared/promise-timeout-fallback' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionEvictionContext = { sessionId: string @@ -72,8 +73,12 @@ export const STRUCTURED_AGENT_SESSION_EVICTION_STEPS: readonly StructuredAgentSe await withTimeout(context.eventSink.drained(), SNAPSHOT_DRAIN_TIMEOUT_MS, null) try { context.beforeProviderChildStop() - } catch { - console.warn('[structured-agent-session] capturing recovery witness failed') + } catch (error) { + traceAgentSessionError({ + step: 'recovery-witness-capture', + sessionId: context.sessionId, + error + }) } } }, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-delivery.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-delivery.ts index ed2e48fd562b..d5b001ddfb6a 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-delivery.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-delivery.ts @@ -21,6 +21,7 @@ import type { import { structuredAgentSessionConversationFence } from './structured-agent-session-provider-child' import { structuredAgentSessionFailureWordsContext } from './structured-agent-session-send-preparation' import { recoverStructuredRewind } from './structured-rewind-recovery' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionConversationDelivery = { loop: StructuredAgentSessionDeliveryLoop @@ -70,7 +71,6 @@ export function createStructuredAgentSessionConversationDelivery(input: { deps.store.getRecord(sessionId), sessions.get(sessionId)?.journal ), - onError: (sessionId, error) => deps.onEventSinkError?.({ sessionId, error }), record: (sessionId) => deps.store.getRecord(sessionId), flushStreamedEvents: input.flushStreamedEvents, now: () => deps.now?.() ?? Date.now() @@ -107,7 +107,7 @@ export function createStructuredAgentSessionConversationDelivery(input: { }) .catch((error: unknown) => { wakesQueued.delete(sessionId) - deps.onEventSinkError?.({ sessionId, error }) + traceAgentSessionError({ step: 'delivery-wake', sessionId, error }) }) } // A chat open before its owner's death was proven revises what its open settled. Queued, never @@ -120,7 +120,9 @@ export function createStructuredAgentSessionConversationDelivery(input: { resettleOpenStructuredAgentSessionConversation(deps, sessionId, sessions.get(sessionId)) ) ) - .catch((error: unknown) => deps.onEventSinkError?.({ sessionId, error })) + .catch((error: unknown) => + traceAgentSessionError({ step: 'death-evidence-resettle', sessionId, error }) + ) } }) return { @@ -151,6 +153,6 @@ async function settleInterruptedCommands( try { await recoverStructuredRewind(deps.store, sessionId, session.journal, fence) } catch (error) { - deps.onEventSinkError?.({ sessionId, error }) + traceAgentSessionError({ step: 'rewind-recovery', sessionId, error }) } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-lifetime.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-lifetime.ts index f2140c98fbc7..e1ccc6b0ce16 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-lifetime.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-lifetime.ts @@ -30,6 +30,7 @@ import { } from './structured-agent-session-provider-child' import { releaseStoredStructuredAgentSessionOwner } from './structured-agent-session-lease-release' import { settleStructuredAgentSessionDeadGeneration } from './structured-agent-session-dead-generation-settlement' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionLifetimeContext = { deps: StructuredAgentSessionHostDeps @@ -45,7 +46,7 @@ export type StructuredAgentSessionLifetimeContext = { } } -type ConversationCloseDeps = Pick & { +type ConversationCloseDeps = { store: Pick } @@ -62,7 +63,7 @@ export async function abandonQueuedStructuredAgentSessionMessages( structuredAgentSessionConversationFence(deps.store, sessionId), agentSessionFailureWords(agentSessionFailureFact('chatClosed'), { surface: 'rejection' }) ) - .catch((error: unknown) => deps.onEventSinkError?.({ sessionId, error })) + .catch((error: unknown) => traceAgentSessionError({ step: 'queued-abandon', sessionId, error })) } /** The wind-down this host owes for the session's child. A live child always owes one, whatever a @@ -100,7 +101,6 @@ export async function stopStructuredAgentSessionAgentUnderSerialize( const owed = owedProviderChildWindDown(session) session.owesProviderChildWindDown = owed const stopping = session.child - let settlementError: unknown const eviction: StructuredAgentSessionEvictionContext = { sessionId, // The retry must not re-stop a child the adapter already proved gone, so this stays honest. @@ -137,15 +137,11 @@ export async function stopStructuredAgentSessionAgentUnderSerialize( settlementId: `expected-close:${sessionId}:${fence}:${owed?.generation ?? 'unknown'}`, pendingSubmissionReason: 'provider_closed_before_acknowledgement', verdict: { state: 'interrupted', completedAt: context.now() }, - showUnexpectedExitOutcome: false, - onError: (id, error) => { - settlementError = error - context.deps.onEventSinkError?.({ sessionId: id, error }) - } + showUnexpectedExitOutcome: false }) - if (!settled) { + if (!settled.ok) { // Without the cause the log names the step and nothing else. - throw new Error('dead generation work settlement failed', { cause: settlementError }) + throw new Error('dead generation work settlement failed', { cause: settled.error }) } }, releaseLease: async () => { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.test.ts index 5f336345b5e6..c129facf9f0a 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.test.ts @@ -13,6 +13,11 @@ import { } from '../agent-session-journal/journal-host-database-test-support' import { StructuredAgentSessionHostRuntimeState } from './structured-agent-session-host-runtime-state' import type { StructuredAgentSessionHostDeps } from './structured-agent-session-host' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const NOW = 1_800_000_000_000 @@ -70,7 +75,7 @@ function runtimeState( claimKeyId: 'key-1', probeOwner } as StructuredAgentSessionHostDeps - return new StructuredAgentSessionHostRuntimeState(deps) + return new StructuredAgentSessionHostRuntimeState(deps, () => {}) } function liveRecord(): AgentSessionRecord { @@ -129,7 +134,6 @@ describe('host runtime-state owner probe', () => { it('does not force-close a provider for transient lease probe errors', async () => { const onEventSinkFailure = vi.fn() - const onEventSinkError = vi.fn() const probeOwner = vi.fn(async () => { throw new Error('lease probe unavailable') }) @@ -143,8 +147,7 @@ describe('host runtime-state owner probe', () => { adapter: {}, journalDatabase: openTestJournalHostDatabase(stateDirectory), claimKeyId: 'key-1', - probeOwner, - onEventSinkError + probeOwner } as unknown as StructuredAgentSessionHostDeps const state = new StructuredAgentSessionHostRuntimeState(deps, onEventSinkFailure) @@ -152,7 +155,8 @@ describe('host runtime-state owner probe', () => { state as unknown as { leaseRenewer: { renewNow: () => Promise } } ).leaseRenewer.renewNow() - expect(onEventSinkError).toHaveBeenCalledWith({ + expect(traceAgentSessionError).toHaveBeenCalledWith({ + step: 'lease-probe', sessionId: record.sessionId, error: expect.any(Error) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.ts index 63f37a37590e..e59e4b4c0529 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-runtime-state.ts @@ -8,25 +8,22 @@ import { import type { StructuredAgentSessionHostDeps } from './structured-agent-session-host' import { StructuredAgentSessionLeaseRenewer } from './structured-agent-session-lease-renewer' import { resolveStructuredSessionRecovery } from './structured-agent-session-recovery-resolution' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export class StructuredAgentSessionHostRuntimeState { private readonly eventSinks = new Map() private readonly leaseRenewer: StructuredAgentSessionLeaseRenewer - private readonly onEventSinkFailure?: (sessionId: string, error: unknown) => void constructor( private readonly deps: StructuredAgentSessionHostDeps, - onEventSinkFailure?: (sessionId: string, error: unknown) => void + /** Forces the session's provider down: its journal can no longer take what it writes. */ + private readonly onEventSinkFailure: (sessionId: string, error: unknown) => void ) { - this.onEventSinkFailure = onEventSinkFailure this.leaseRenewer = new StructuredAgentSessionLeaseRenewer({ store: deps.store, probe: (record) => this.probeRecord(record), ...(deps.probeOwners ? { probeMany: deps.probeOwners } : {}), - now: () => deps.now?.() ?? Date.now(), - // Lease/ownership failures are transient and stay on the visible lease-error path. - // Only deferred sink I/O failures are terminal and may force-close a provider. - onError: ({ sessionId, error }) => deps.onEventSinkError?.({ sessionId, error }) + now: () => deps.now?.() ?? Date.now() }) } @@ -67,11 +64,11 @@ export class StructuredAgentSessionHostRuntimeState { mintEventSink(sessionId: string): DeferredStructuredAgentSessionEventSink { const minted: DeferredStructuredAgentSessionEventSink = createDeferredStructuredAgentSessionEventSink({ - onError: (error) => { - this.deps.onEventSinkError?.({ sessionId, error }) + onFailure: (error) => { + traceAgentSessionError({ step: 'event-sink', sessionId, error }) // Only the session's own sink may force its provider down; an attempt's never is. if (this.eventSinks.get(sessionId) === minted) { - this.onEventSinkFailure?.(sessionId, error) + this.onEventSinkFailure(sessionId, error) } } }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-tabs.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-tabs.ts index 8a18040daf35..6ebf10703b7d 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-tabs.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-tabs.ts @@ -1,4 +1,5 @@ import type { AgentSessionRecord } from '../../../shared/agent-session-record' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** * Chat-tab visibility is the deletion funnel: every path that removes a chat as a user-facing @@ -24,9 +25,11 @@ export function setStructuredAgentSessionTabVisibility( tabId?: string ): Promise { if (!visible) { - void host.restartResume.dismiss([sessionId]).catch(() => { - console.warn('[structured-agent-session] forgetting recovery records on chat close failed') - }) + void host.restartResume + .dismiss([sessionId]) + .catch((error: unknown) => + traceAgentSessionError({ step: 'recovery-records-forget', sessionId, error }) + ) } return host.deps.store.setSessionTabVisibility(sessionId, visible, tabId) } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.test.ts index aa8692a0c73f..81976971fc64 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.test.ts @@ -108,7 +108,9 @@ describe('structured agent-session host teardown', () => { await teardown expect(cleaned).toHaveBeenCalledTimes(4) expect(warning).toHaveBeenCalledWith( - '[structured-agent-session] recording recovery capsule failed' + '[agent-session] recovery-capsule-record failed', + {}, + expect.any(String) ) expect(vi.getTimerCount()).toBe(0) } finally { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.ts index 4ce0b3885adf..c749e31876d6 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-teardown.ts @@ -17,6 +17,7 @@ import { } from './structured-agent-session-host-lifetime' import { withTimeout } from '../../../shared/promise-timeout-fallback' import type { StructuredAgentSessionHostSession } from './structured-agent-session-host-types' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionTeardownPhase = { name: string @@ -73,8 +74,8 @@ export function structuredAgentSessionHostTeardownPhases(collaborators: { run: () => { try { collaborators.beginResumeMarkers() - } catch { - console.warn('[structured-agent-session] capturing recovery witnesses failed') + } catch (error) { + traceAgentSessionError({ step: 'recovery-witness-begin', error }) } } }, @@ -89,9 +90,7 @@ export function structuredAgentSessionHostTeardownPhases(collaborators: { name: 'record-resume-markers', run: () => withPhaseTimeout(collaborators.recordResumeMarkers, RESUME_MARKER_RECORD_TIMEOUT_MS).catch( - () => { - console.warn('[structured-agent-session] recording recovery capsule failed') - } + (error: unknown) => traceAgentSessionError({ step: 'recovery-capsule-record', error }) ) }, { name: 'flush-event-sinks', run: () => collaborators.runtimeState.flushAllEventSinks() } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host-types.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host-types.ts index 80ea85e86835..cf640cf86acc 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host-types.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host-types.ts @@ -119,7 +119,6 @@ export type StructuredAgentSessionHostDeps = { idleSweep?: { intervalMs?: number; idleMs?: number } /** Whether an orchestration dispatch still owns this session's worker; absent answers no. */ hasOpenDispatch?: (record: AgentSessionRecord) => boolean - onEventSinkError?: (input: { sessionId: string; error: unknown }) => void /** Every status projection this host publishes. `replay` marks a re-projection of state the host * already knew (restore, an arriving subscriber) rather than a fresh journal edge. */ onSessionStatusChanged?: ( diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-host.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-host.ts index 79a129118ee0..644b6e7ceab8 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-host.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-host.ts @@ -68,7 +68,6 @@ export class StructuredAgentSessionHost { this.subscribers.publish(sessionId, journal) this.conversationDelivery.afterCommit(sessionId, journal) }, - onDeliveryError: (sessionId, error) => this.deps.onEventSinkError?.({ sessionId, error }), onOpened: (sessionId) => this.queued.drain.schedule(sessionId), now: () => this.now() }) @@ -156,8 +155,7 @@ export class StructuredAgentSessionHost { ), publishStatus: this.clientDelivery.publishStatusAndSettlement, serialize: (sessionId, task) => this.tasks.trackAttach(this.serialize(sessionId, task)), - now: () => this.now(), - onBarrierError: (sessionId, error) => deps.onEventSinkError?.({ sessionId, error }) + now: () => this.now() }) this.restartResume = createStructuredAgentSessionRestartResume( deps, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.test.ts index 25288dc64905..e6a5a50ded0f 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.test.ts @@ -18,6 +18,11 @@ import { type RestTestRig } from './structured-agent-session-rest-test-rig' import { StructuredAgentSessionIdleSweep } from './structured-agent-session-idle-sweep' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) let rig: RestTestRig @@ -306,12 +311,11 @@ describe('the idle sweep with no child running (P2-22 ii)', () => { hasOpenDispatch: () => false, stopAgent, stopStartingAgent: stopAgent, - closeConversation, - onError: (_id, error) => { - throw error - } + closeConversation }) + vi.mocked(traceAgentSessionError).mockClear() await sweep.tick() + expect(traceAgentSessionError).not.toHaveBeenCalled() expect(stopAgent).not.toHaveBeenCalled() expect(closeConversation).toHaveBeenCalledWith(SESSION) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.ts index 1fc223808f6b..6708353b0f1d 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-idle-sweep.ts @@ -14,6 +14,7 @@ import { isQueuedAgentJournalSubmission } from '../../../shared/agent-session-qu import type { AgentJournalRenderItem } from '../../../shared/agent-session-journal-types' import type { AgentSessionBackgroundTaskState } from '../../../shared/agent-session-wire' import type { StructuredAgentSessionHostSession } from './structured-agent-session-host-types' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export const STRUCTURED_AGENT_SESSION_IDLE_SWEEP_INTERVAL_MS = 5 * 60_000 export const STRUCTURED_AGENT_SESSION_IDLE_MS = 30 * 60_000 @@ -34,7 +35,6 @@ export type StructuredAgentSessionIdleSweepDeps = { stopAgent: (sessionId: string) => Promise stopStartingAgent: (sessionId: string) => Promise closeConversation: (sessionId: string) => Promise - onError: (sessionId: string, error: unknown) => void intervalMs?: number idleMs?: number } @@ -84,7 +84,9 @@ export class StructuredAgentSessionIdleSweep { [...this.deps.sessions.keys()].map((sessionId) => this.deps .serialize(sessionId, () => this.tickUnderSerialize(sessionId)) - .catch((error: unknown) => this.deps.onError(sessionId, error)) + .catch((error: unknown) => + traceAgentSessionError({ step: 'idle-sweep', sessionId, error }) + ) ) ) } finally { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-late-settlement.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-late-settlement.test.ts index 510384f3e484..e1810671b8df 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-late-settlement.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-late-settlement.test.ts @@ -289,6 +289,40 @@ describe('settling a send the provider proves it received after the ack window', ]) }) + it('reports once when not even the doubt about a dispatch can be recorded', async () => { + const settleError = new Error('settlement write refused') + const doubtError = new Error('doubt write refused') + const resolveDispatch = journal().resolveDispatch.bind(journal()) + const resolve = vi.spyOn(journal(), 'resolveDispatch').mockImplementation(async (input) => { + if (input.state === 'accepted') { + throw settleError + } + if (input.state === 'unknown') { + throw doubtError + } + return resolveDispatch(input) + }) + const warned = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const line = '[agent-session] dispatch-doubt-record failed' + const doubtReports = () => warned.mock.calls.filter(([message]) => message === line) + try { + await host.send(CALLER, sendParams('an outcome nothing could record')) + await vi.waitFor(() => expect(doubtReports()).toHaveLength(1)) + expect(doubtReports()).toEqual([[line, { sessionId: SESSION }, doubtError]]) + // The settlement's own failure is still what the delivery loop reports. + await vi.waitFor(() => + expect(warned).toHaveBeenCalledWith( + '[agent-session] delivery-loop failed', + { sessionId: SESSION }, + settleError + ) + ) + } finally { + resolve.mockRestore() + warned.mockRestore() + } + }) + it('leaves an already accepted send alone', async () => { const params = sendParams('ordinary send') await host.send(CALLER, params) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.test.ts index 9399e4d0242b..f5951ea89e74 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.test.ts @@ -6,9 +6,15 @@ import { agentSessionLeaseFixture, agentSessionRecordFixture } from '../../../shared/agent-session-record.test-fixture' +import type { AgentSessionOwnerProbe } from '../../../shared/agent-session-lease-adjudication' import type { AgentSessionRecordStore } from '../../runtime/agent-session-record-store' import { openTestAgentSessionRecordStore } from '../../runtime/agent-session-record-store-test-harness' import { StructuredAgentSessionLeaseRenewer } from './structured-agent-session-lease-renewer' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const NOW = 1_800_000_000_000 const roots: string[] = [] @@ -144,7 +150,7 @@ describe('structured agent-session lease renewal', () => { } return records[0]! }) - const onError = vi.fn() + vi.mocked(traceAgentSessionError).mockClear() const renewer = new StructuredAgentSessionLeaseRenewer({ store: { listRecords: () => records, @@ -155,15 +161,15 @@ describe('structured agent-session lease renewal', () => { outcome: 'identity-matched' as const, matchedOn: ['spawn-token' as const] }), - now: () => NOW + 10_000, - onError + now: () => NOW + 10_000 }) await renewer.renewNow() expect(renewLeases).toHaveBeenCalledOnce() expect(renewLease).toHaveBeenCalledTimes(2) - expect(onError).toHaveBeenCalledWith({ + expect(traceAgentSessionError).toHaveBeenCalledExactlyOnceWith({ + step: 'lease-renewal', sessionId: 'session-b', error: expect.objectContaining({ message: 'agent_session_checkpoint_stale' }) }) @@ -241,18 +247,18 @@ describe('structured agent-session lease renewal', () => { it('stops extending the lease when child proof is no longer sufficient', async () => { const store = await liveStore() - const onError = vi.fn() + vi.mocked(traceAgentSessionError).mockClear() const renewer = new StructuredAgentSessionLeaseRenewer({ store, probe: async () => ({ outcome: 'indeterminate', reason: 'probe unavailable' }), - now: () => NOW + 10_000, - onError + now: () => NOW + 10_000 }) await renewer.renewNow() expect(store.getRecord('session-renewal')?.lease.lastRenewedAt).toBe(NOW) - expect(onError).toHaveBeenCalledWith({ + expect(traceAgentSessionError).toHaveBeenCalledWith({ + step: 'lease-renewal', sessionId: 'session-renewal', error: expect.any(Error) }) @@ -281,4 +287,206 @@ describe('structured agent-session lease renewal', () => { expect(probe).not.toHaveBeenCalled() expect(store.getRecord('session-renewal')?.lease.lastRenewedAt).toBe(NOW) }) + + describe('a failure that repeats every tick', () => { + function liveRecord(sessionId: string) { + return agentSessionRecordFixture( + agentSessionLeaseFixture({ + sessionId, + runtimeKind: 'native', + runtimeFence: 1, + ownerProcess: { + hostId: 'local', + pid: 4200, + processStartTimeMs: NOW - 1_000, + spawnToken: 'spawn-a' + }, + reservedSpawnToken: 'spawn-a', + lastRenewedAt: NOW, + leaseDeadlineAt: NOW + 30_000 + }) + ) + } + + /** Each tick's renewal throws whatever `failure` returns for the session, or renews when it + * holds or returns null. */ + async function stuckRenewer( + sessionIds: string[], + probe: () => Promise = async () => ({ + outcome: 'identity-matched', + matchedOn: ['spawn-token'] + }), + probeMany?: () => Promise> + ) { + const state: { + failure: ((sessionId: string) => Error | null) | null + records: string[] + } = { + failure: () => new Error('agent_session_ownership_unknown'), + records: sessionIds + } + const store = await liveStore() + vi.spyOn(store, 'listRecords').mockImplementation(() => state.records.map(liveRecord)) + vi.spyOn(store, 'renewLeases').mockRejectedValue(new Error('batch refused')) + vi.spyOn(store, 'renewLease').mockImplementation(async (renewal) => { + const failure = state.failure?.(renewal.sessionId) + if (failure) { + throw failure + } + return liveRecord(renewal.sessionId) + }) + const renewer = new StructuredAgentSessionLeaseRenewer({ + store, + probe, + ...(probeMany ? { probeMany } : {}), + now: () => NOW + 10_000 + }) + return { state, renewer } + } + + async function ticks(renewer: StructuredAgentSessionLeaseRenewer, count: number) { + for (let tick = 0; tick < count; tick += 1) { + await renewer.renewNow() + } + } + + const renewalRecords = () => + vi + .mocked(traceAgentSessionError) + .mock.calls.filter(([report]) => report.step === 'lease-renewal') + + it('records it once, however many ticks it repeats', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { renewer } = await stuckRenewer(['session-a']) + + await ticks(renewer, 5) + + expect(renewalRecords()).toEqual([ + [ + { + step: 'lease-renewal', + sessionId: 'session-a', + error: expect.objectContaining({ message: 'agent_session_ownership_unknown' }) + } + ] + ]) + }) + + it('keys a store error on its code, not its per-attempt temp path', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { state, renewer } = await stuckRenewer(['session-a']) + let attempt = 0 + state.failure = () => + Object.assign( + new Error(`EACCES: permission denied, open 'records.${(attempt += 1)}.tmp'`), + { + code: 'EACCES' + } + ) + + await ticks(renewer, 3) + + expect(renewalRecords()).toHaveLength(1) + }) + + it('records it again after the session renews, and when the failure changes', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { state, renewer } = await stuckRenewer(['session-a']) + const unknown = state.failure + + await ticks(renewer, 2) + state.failure = null + await ticks(renewer, 1) + state.failure = unknown + await ticks(renewer, 2) + expect(renewalRecords()).toHaveLength(2) + + state.failure = () => new Error('agent_session_checkpoint_stale') + await ticks(renewer, 2) + expect(renewalRecords().map(([report]) => String(report.error))).toEqual([ + 'Error: agent_session_ownership_unknown', + 'Error: agent_session_ownership_unknown', + 'Error: agent_session_checkpoint_stale' + ]) + }) + + it('forgets a session that stops being renewable', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { state, renewer } = await stuckRenewer(['session-a']) + + await ticks(renewer, 1) + state.records = [] + await ticks(renewer, 1) + state.records = ['session-a'] + await ticks(renewer, 1) + + expect(renewalRecords()).toHaveLength(2) + }) + + it('records a probe that keeps failing once', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { renewer } = await stuckRenewer(['session-a'], async () => { + throw new Error('probe unavailable') + }) + + await ticks(renewer, 3) + + expect( + vi + .mocked(traceAgentSessionError) + .mock.calls.filter(([report]) => report.step === 'lease-probe') + ).toHaveLength(1) + }) + + it('records a batch probe that keeps failing once per session', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { renewer } = await stuckRenewer(['session-a', 'session-b'], undefined, async () => { + throw new Error('owner probe unavailable') + }) + + await ticks(renewer, 3) + + expect( + vi + .mocked(traceAgentSessionError) + .mock.calls.filter(([report]) => report.step === 'lease-probe') + .map(([report]) => report.sessionId) + ).toEqual(['session-a', 'session-b']) + }) + + it("clears only the renewed session's failure", async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { state, renewer } = await stuckRenewer(['session-a', 'session-b']) + const unknown = state.failure + + await ticks(renewer, 2) + state.failure = (sessionId) => + sessionId === 'session-b' ? null : new Error('agent_session_ownership_unknown') + await ticks(renewer, 1) + state.failure = unknown + await ticks(renewer, 2) + + expect(renewalRecords().map(([report]) => report.sessionId)).toEqual([ + 'session-a', + 'session-b', + 'session-b' + ]) + }) + + it('records an error it cannot key without failing the tick', async () => { + vi.mocked(traceAgentSessionError).mockClear() + const { state, renewer } = await stuckRenewer(['session-a']) + state.failure = () => + Object.defineProperty(new Error('agent_session_ownership_unknown'), 'name', { + get: () => { + throw new Error('hostile name') + } + }) + + await expect(renewer.renewNow()).resolves.toBeUndefined() + await expect(renewer.renewNow()).resolves.toBeUndefined() + + expect(renewalRecords()).toHaveLength(1) + }) + }) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.ts index a61e11b6f4f1..b53a568ab975 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-lease-renewer.ts @@ -4,15 +4,23 @@ import { AGENT_SESSION_LEASE_TTL_MS, type AgentSessionRecordStore } from '../../runtime/agent-session-record-store' +import { + traceAgentSessionError, + type AgentSessionErrorStep +} from '../../observability/agent-session-error-trace' const RENEW_INTERVAL_MS = Math.floor(AGENT_SESSION_LEASE_TTL_MS / 3) export class StructuredAgentSessionLeaseRenewer { private timer: ReturnType | null = null private running = false - /** The tick in flight. Never rejects: the timer path reports renewal failures through `onError`, - * and stopping must not turn one into a teardown failure as well. */ + /** The tick in flight. Never rejects: the timer path reports renewal failures, and stopping must + * not turn one into a teardown failure as well. Lease failures are transient: reported, never + * a reason to force a provider down. */ private inFlight: Promise = Promise.resolve() + /** A stuck lease fails every tick (one store EACCES left ownership_unknown every 10 s, forever), + * so a session's failure is recorded once until it renews or the failure changes. */ + private readonly recordedFailures = new Map() constructor( private readonly input: { @@ -22,7 +30,6 @@ export class StructuredAgentSessionLeaseRenewer { records: readonly AgentSessionRecord[] ) => Promise> now: () => number - onError?: (input: { sessionId: string; error: unknown }) => void intervalMs?: number } ) {} @@ -71,6 +78,12 @@ export class StructuredAgentSessionLeaseRenewer { // keeps an orphan pid's lease reading as a healthy owner. record.lease.handoffStage !== 'recovering' ) + const renewable = new Set(records.map((record) => record.sessionId)) + for (const sessionId of this.recordedFailures.keys()) { + if (!renewable.has(sessionId)) { + this.recordedFailures.delete(sessionId) + } + } const probes = await this.probe(records) const renewals: { sessionId: string @@ -103,15 +116,31 @@ export class StructuredAgentSessionLeaseRenewer { ) } results.forEach((result, index) => { + const renewal = renewals[index] + if (!renewal) { + return + } if (result.status === 'rejected') { - const renewal = renewals[index] - if (renewal) { - this.input.onError?.({ sessionId: renewal.sessionId, error: result.reason }) - } + this.recordFailure('lease-renewal', renewal.sessionId, result.reason) + } else { + this.recordedFailures.delete(renewal.sessionId) } }) } + private recordFailure( + step: Extract, + sessionId: string, + error: unknown + ): void { + const failure = `${step}:${leaseFailureKey(error)}` + if (this.recordedFailures.get(sessionId) === failure) { + return + } + this.recordedFailures.set(sessionId, failure) + traceAgentSessionError({ step, sessionId, error }) + } + private async probe( records: readonly AgentSessionRecord[] ): Promise> { @@ -126,15 +155,29 @@ export class StructuredAgentSessionLeaseRenewer { if (result.status === 'fulfilled') { probes.set(record.sessionId, result.value) } else { - this.input.onError?.({ sessionId: record.sessionId, error: result.reason }) + this.recordFailure('lease-probe', record.sessionId, result.reason) } } return probes } catch (error) { for (const record of records) { - this.input.onError?.({ sessionId: record.sessionId, error }) + this.recordFailure('lease-probe', record.sessionId, error) } return new Map() } } } + +/** A store error's code, not its message: EACCES names a fresh temp file on every attempt. */ +function leaseFailureKey(error: unknown): string { + // Never throws: a hostile getter or toString would otherwise reject the interval's tick. + try { + if (!(error instanceof Error)) { + return String(error) + } + const code = 'code' in error ? error.code : undefined + return `${error.name}:${typeof code === 'string' || typeof code === 'number' ? code : error.message}` + } catch { + return 'unkeyable' + } +} diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.test.ts index 71750505fef1..088cb5a8782c 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.test.ts @@ -127,7 +127,10 @@ it.each([1, 2])( expect(result).toEqual(refusal) expect(run).toHaveBeenCalledOnce() expect(dispatch).not.toHaveBeenCalled() - expect(JSON.stringify(warning.mock.calls)).not.toContain('private unbounded disk detail') + expect(warning).toHaveBeenCalled() + expect(warning.mock.calls.flat().map(String).join(' ')).not.toContain( + 'private unbounded disk detail' + ) } ) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.ts index e4675bfefb14..e66d00bac311 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-operation-settlement.ts @@ -2,6 +2,7 @@ import type { AgentSessionMutationEnvelope } from '../../../shared/agent-session import type { AgentSessionRecordStore } from '../../runtime/agent-session-record-store' import type { MutationPlan } from './structured-agent-session-mutation-plans' import type { AgentSessionTurnContext, TurnOutcome } from './structured-agent-session-turns' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** Only thrown while the provider dispatch is still unreachable. */ export class AgentSessionPreDispatchError extends Error { @@ -52,14 +53,19 @@ export async function runSettledAgentSessionMutation(input: { if (input.plan.markUnknownBeforeRun && error instanceof AgentSessionPreDispatchError) { throw error } + const { sessionId } = input.envelope try { await settle({ status: 'unknown' }) - } catch { + } catch (settleError) { // Bookkeeping must not replace the operation's proof of whether dispatch began. - console.warn('[structured-agent-session] operation uncertainty persistence failed') + traceAgentSessionError({ + step: 'operation-uncertainty-persist', + sessionId, + error: settleError + }) } if (outcome && !outcome.ok) { - console.warn('[structured-agent-session] refused operation settlement failed') + traceAgentSessionError({ step: 'refused-operation-settlement', sessionId, error }) return outcome } throw error diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-operation-start-refusal.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-operation-start-refusal.test.ts index 7700a616b382..b0658b71d35b 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-operation-start-refusal.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-operation-start-refusal.test.ts @@ -31,7 +31,11 @@ describe('an operation whose agent start throws', () => { message: "The agent couldn't restart." } }) - expect(warn).toHaveBeenCalledWith(expect.stringContaining('starting the agent'), cause) + expect(warn).toHaveBeenCalledWith( + '[agent-session] operation-agent-start failed', + { sessionId: SESSION }, + cause + ) warn.mockRestore() }) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-pre-spawn-first-answer.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-pre-spawn-first-answer.test.ts index db9406785f87..022c32454a78 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-pre-spawn-first-answer.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-pre-spawn-first-answer.test.ts @@ -157,7 +157,8 @@ describe('a create that fails before any process spawns', () => { } // What failed is kept for the log. expect(warn).toHaveBeenCalledWith( - '[agent-session] provider start failed:', + '[agent-session] provider-start failed', + expect.anything(), expect.objectContaining({ message: raw }) ) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.ts index 8f3c0390aaa1..e1ad7d2847e2 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-provider-started.ts @@ -17,6 +17,7 @@ import type { } from './structured-agent-session-host-types' import { nativeSessionOptionsFromReport } from './structured-agent-session-option-restoration' import { markProviderChildStarted } from './structured-agent-session-provider-child' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionProviderStartedContext = { deps: StructuredAgentSessionHostDeps @@ -24,7 +25,6 @@ export type StructuredAgentSessionProviderStartedContext = { serialize: (sessionId: string, task: () => Promise) => Promise now: () => number publishStatus?: (sessionId: string) => void - onBarrierError: (sessionId: string, error: unknown) => void } export function settleStructuredAgentSessionProviderStarted( @@ -46,7 +46,7 @@ export function settleStructuredAgentSessionProviderStarted( try { await persistStartedOptions(context, event) } catch (error) { - context.onBarrierError(event.sessionId, error) + traceAgentSessionError({ step: 'started-options-persist', sessionId: event.sessionId, error }) } finally { context.publishStatus?.(event.sessionId) } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.test.ts index aa9d31cbf105..3fa5bac7fd7d 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.test.ts @@ -343,6 +343,38 @@ describe('held drafts', () => { }) expect(await drafts()).toHaveLength(0) }) + it('a hold that cannot be written after a failed conversion is reported once, and the failure still surfaces', async () => { + const working = await workingSend() + const queued = await send('conversion and hold both fail', 'queue-if-active').result + if (!queued.ok || !('queued' in queued.value)) { + throw new Error('expected a queued receipt') + } + const append = vi + .spyOn(AgentSessionJournal.prototype, 'appendSubmission') + .mockRejectedValueOnce(new Error('disk full')) + const holdError = new Error('hold write refused') + const hold = vi.spyOn(JournalQueuedMessages.prototype, 'hold').mockRejectedValueOnce(holdError) + const warned = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const line = '[agent-session] queued-send-failure-hold failed' + const holdReports = () => warned.mock.calls.filter(([message]) => message === line) + try { + await settleAccepted(working, 'a') + await eventually(async () => expect(holdReports()).toHaveLength(1)) + expect(holdReports()).toEqual([[line, { sessionId: SESSION }, holdError]]) + // The conversion's own failure is still rethrown to the drain, which reports it. + await eventually(async () => + expect(warned).toHaveBeenCalledWith( + '[agent-session] queued-drain failed', + { sessionId: SESSION }, + expect.objectContaining({ message: 'disk full' }) + ) + ) + } finally { + append.mockRestore() + hold.mockRestore() + warned.mockRestore() + } + }) }) describe('Stop and Delete', () => { @@ -524,7 +556,11 @@ describe('Stop and Delete', () => { const warned = vi.spyOn(console, 'warn').mockImplementation(() => undefined) try { expect(await stop()).toMatchObject({ ok: true, value: { cancelled: true } }) - expect(warned).toHaveBeenCalledWith(expect.stringContaining('queue pause'), expect.anything()) + expect(warned).toHaveBeenCalledWith( + '[agent-session] stop-queue-pause failed', + expect.anything(), + expect.objectContaining({ message: 'disk full' }) + ) } finally { record.mockRestore() warned.mockRestore() diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.ts index b6d9d2a90beb..eace71f69fb0 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-messages.ts @@ -30,6 +30,7 @@ import { structuredAgentSessionHostInstance, structuredQueuePause } from './structured-agent-session-queued-pause' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** Budget at accept, in the send schema's own unit (`Buffer.byteLength` of the * serialized blocks); refused readably rather than trimmed. */ @@ -263,7 +264,6 @@ export type QueuedMessageDrainDeps = { conversationFence: (sessionId: string) => number /** The consumed submission is ordinary #22821 work from here on. */ wakeDelivery: (sessionId: string) => void - onError: (sessionId: string, error: unknown) => void } /** @@ -312,7 +312,7 @@ export class StructuredAgentSessionQueuedMessageDrain { }) .catch((error: unknown) => { this.scheduled.delete(sessionId) - this.deps.onError(sessionId, error) + traceAgentSessionError({ step: 'queued-drain', sessionId, error }) }) } @@ -326,7 +326,7 @@ export class StructuredAgentSessionQueuedMessageDrain { if (journal.queuedMessages.settlementOwed() || journal.queuedMessages.deliveredByEchoOwed()) { // A live per-row hook was skipped; heal now, before a draft sends, rather than at reopen. await journal.queuedMessages.settleOwed().catch((error: unknown) => { - this.deps.onError(sessionId, error) + traceAgentSessionError({ step: 'queued-owed-settlement', sessionId, error }) }) } const next = oldestActionableQueuedMessage(journal) @@ -372,7 +372,9 @@ export class StructuredAgentSessionQueuedMessageDrain { // no automatic retry loop. await journal.queuedMessages .hold({ messageIds: [next.messageId], reason: QUEUED_MESSAGE_PAUSED_SEND_FAILED }) - .catch(() => {}) + .catch((holdError: unknown) => { + traceAgentSessionError({ step: 'queued-send-failure-hold', sessionId, error: holdError }) + }) throw error } this.deps.wakeDelivery(sessionId) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-mutations.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-mutations.ts index 9da974a44a43..30ba137a61e2 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-mutations.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-mutations.ts @@ -41,6 +41,7 @@ import { structuredAgentSessionSendBlock } from './structured-agent-session-send-preparation' import type { AgentSessionTurnContext, TurnOutcome } from './structured-agent-session-turns' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' function invalid(message: string): { ok: false @@ -127,10 +128,7 @@ export async function carryQueuedMessagesToClearReplacement( operationId: input.operationId }) } catch (error) { - console.warn("[agent-session] /clear's queued-draft carry skipped:", { - sessionId: ctx.sessionId, - error: error instanceof Error ? error.message : String(error) - }) + traceAgentSessionError({ step: 'clear-draft-carry', sessionId: ctx.sessionId, error }) } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-pause.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-pause.ts index 1428de75fe63..a9a792816eed 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-pause.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-pause.ts @@ -15,6 +15,7 @@ import { randomUUID } from 'node:crypto' import type { AgentSessionQueuePause } from '../../../shared/agent-session-wire' import type { AgentSessionJournal } from '../agent-session-journal/journal-store' import type { QueuePauseFact } from '../agent-session-journal/queued-message-pause-table' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** A per-process id, minted once per host process like the runtime's own * `runtimeId` (`orca-runtime-runtime-id.ts`); a draft written by another @@ -88,10 +89,7 @@ export async function retireEndedQueuePause( adoptInto: adopt ? hostInstance : null }) } catch (error) { - console.warn("[agent-session] a started turn's queue-pause retirement skipped:", { - sessionId, - error: error instanceof Error ? error.message : String(error) - }) + traceAgentSessionError({ step: 'queue-pause-retire', sessionId, error }) } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-stop.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-stop.ts index 16a9b4aeaf77..eb265afb9032 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-stop.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-stop.ts @@ -12,6 +12,7 @@ import { type QueuedMessageRow } from '../agent-session-journal/queued-message-table' import type { AgentSessionTurnContext, TurnOutcome } from './structured-agent-session-turns' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** The one unsettled-card predicate /clear's carry and the budget share: * waiting or returned. Pending/unknown/accepted deliveries stay outside it. */ @@ -48,19 +49,14 @@ export async function runStopWithQueuePause( await queuedMessages.settleOwed() } } catch (error) { - report(ctx, 'owed settlement', error) + traceAgentSessionError({ step: 'stop-owed-settlement', sessionId: ctx.sessionId, error }) } // Recorded only over a card it holds back — judged in its own transaction, which // still counts an owed return to waiting if that heal failed. await queuedMessages .recordPause('stopped') - .catch((error: unknown) => report(ctx, 'queue pause', error)) - }) -} - -function report(ctx: AgentSessionTurnContext, step: string, error: unknown): void { - console.warn(`[agent-session] Stop's ${step} skipped:`, { - sessionId: ctx.sessionId, - error: error instanceof Error ? error.message : String(error) + .catch((error: unknown) => + traceAgentSessionError({ step: 'stop-queue-pause', sessionId: ctx.sessionId, error }) + ) }) } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-wiring.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-wiring.ts index 2b193d5cb82f..fa015b4d1bbe 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-queued-wiring.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-queued-wiring.ts @@ -32,8 +32,7 @@ export function wireStructuredAgentSessionQueuedMessages( flushStreamedEvents: (sessionId) => context().flushStreamedEvents(sessionId), conversationFence: (sessionId) => structuredAgentSessionConversationFence(context().deps.store, sessionId), - wakeDelivery: (sessionId) => context().wakeDelivery(sessionId), - onError: (sessionId, error) => context().deps.onEventSinkError?.({ sessionId, error }) + wakeDelivery: (sessionId) => context().wakeDelivery(sessionId) }) return { drain, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-recovered-turn-clock.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-recovered-turn-clock.test.ts index f7d26c154f1f..7f2e9102c790 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-recovered-turn-clock.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-recovered-turn-clock.test.ts @@ -118,7 +118,7 @@ async function sessionWithRunningTurn() { function settleDeadGeneration( journal: AgentSessionJournal, verdict: StructuredAgentSessionTurnVerdict -): Promise { +) { return settleStructuredAgentSessionDeadGeneration({ journal, sessionId: SESSION, @@ -138,7 +138,7 @@ describe('a turn recovery settled after its host went away', () => { async (_label, verdict) => { const session = await sessionWithRunningTurn() session.recoverAt(RECOVERED) - expect(await settleDeadGeneration(session.journal, verdict)).toBe(true) + expect(await settleDeadGeneration(session.journal, verdict)).toEqual({ ok: true }) session.publish() expect(session.summaries.at(-1)).toMatchObject({ diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-resolved-append.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-resolved-append.test.ts index d3c15de933c7..11f04d04fc96 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-resolved-append.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-resolved-append.test.ts @@ -61,7 +61,7 @@ const appendSuffix = describe('resolved revisions', () => { it('reads the row as the journal holds it when each queued revision runs', async () => { const rows = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const bytes = estimateStructuredAgentSessionItemBytes(ROW, text('abc')) for (const suffix of ['a', 'b', 'c']) { expect( @@ -81,7 +81,7 @@ describe('resolved revisions', () => { it('skips a revision that resolves to nothing', async () => { const rows = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.sink.tryReviseResolvedItem?.(1_000, () => null, { turnScope: AGENT_JOURNAL_THREAD_SCOPE }) @@ -93,7 +93,7 @@ describe('resolved revisions', () => { it('publishes a revision in the operation that writes it, within the same reservation', async () => { const rows = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const bytes = estimateStructuredAgentSessionItemBytes(ROW, text('a')) deferred.sink.tryReviseResolvedItemAndPublish?.(bytes, appendSuffix('a'), { turnScope: AGENT_JOURNAL_THREAD_SCOPE @@ -114,7 +114,7 @@ describe('resolved revisions', () => { it('refuses a resolved write larger than the reservation it was admitted with', async () => { const rows = new Map() - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const bytes = estimateStructuredAgentSessionItemBytes(ROW, text('a')) deferred.sink.tryReviseResolvedItem?.( bytes, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-cap.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-cap.test.ts index 9ded5b54d983..bdcc785df0df 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-cap.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-cap.test.ts @@ -35,8 +35,7 @@ it('holds each slot from accept until handover or rejection, and frees it when t } }, awaitSettlement: async () => ({ dispatchState: 'accepted' }), - note: async () => undefined, - onNoteFailed: () => undefined + note: async () => undefined }) const sessions = Array.from({ length: 8 }, (_, index) => `session-${index}`) const outcomes = resumeStructuredAgentSessionsFromRestart( diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.test.ts index 0fe36994cd7c..175f1fde1339 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.test.ts @@ -1,4 +1,4 @@ -import { expect, it, vi } from 'vitest' +import { beforeEach, expect, it, vi } from 'vitest' import { marker, SESSION } from './structured-agent-session-restart-resume-test-harness' import { AGENT_SESSION_RESTART_CONTINUATION_REFUSED_NOTE, @@ -10,6 +10,15 @@ import { startStructuredAgentSessionContinuation, type StructuredAgentSessionContinuationDeps } from './structured-agent-session-restart-continuation' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) + +beforeEach(() => { + vi.mocked(traceAgentSessionError).mockClear() +}) /** The whole continuation: handed over, then its verdict. */ async function continueStructuredAgentSessionAfterRestart( @@ -44,8 +53,7 @@ function dependencies( } : undefined ), - note: vi.fn(async () => undefined), - onNoteFailed: vi.fn() + note: vi.fn(async () => undefined) } } @@ -61,6 +69,22 @@ it('reports an accepted continuation and records its note', async () => { expect(deps.note).toHaveBeenCalledOnce() }) +// Best effort, but never silent: a swallowed note is how this regressed unnoticed once already. +it('reports a note it could not write without failing the continuation', async () => { + const deps = dependencies('accepted') + const failure = new Error('journal closed') + deps.note.mockRejectedValueOnce(failure) + + await expect( + continueStructuredAgentSessionAfterRestart(deps, SESSION, marker(), 'operation-1') + ).resolves.toEqual({ sessionId: SESSION, outcome: 'continued' }) + expect(traceAgentSessionError).toHaveBeenCalledExactlyOnceWith({ + step: 'restart-continuation-note', + sessionId: SESSION, + error: failure + }) +}) + const UNCONFIRMED = [SESSION, AGENT_SESSION_RESTART_CONTINUATION_UNCONFIRMED_NOTE, 'warning'] const REFUSED = [SESSION, AGENT_SESSION_RESTART_CONTINUATION_REFUSED_NOTE, 'error'] const NOT_CONNECTED = [SESSION, AGENT_SESSION_RESTART_NOT_CONNECTED_NOTE, 'error'] diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.ts index 8038e90e1fc4..376f19618f96 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-continuation.ts @@ -31,6 +31,7 @@ import { import { AgentSessionPreDispatchError } from './structured-agent-session-operation-settlement' import { restartContinuationEnvelope } from './structured-agent-session-restart-continuation-envelope' import type { AgentSessionResumeMarker } from '../../../shared/agent-session-resume-marker' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** * All four dispatch states are preserved, never collapsed into transport success. @@ -71,7 +72,6 @@ export type StructuredAgentSessionContinuationHost = { sessionId: string, clientMessageId: string ) => Promise<{ value: AgentSessionSendResult } | undefined> - onNoteFailed: (sessionId: string, error: unknown) => void now: () => number /** Whether the marker is still an offer. Asked at acceptance, inside the session lock, so the * first message accepted since the restart decides: the user's, or this continuation. */ @@ -103,7 +103,6 @@ export function restartContinuationDeps( agentSessionSendSubmission( (await host.awaitSendHandedOver(sessionId, clientMessageId))?.value ), - onNoteFailed: host.onNoteFailed, note: restartNoteWriter(host) } } @@ -183,11 +182,10 @@ export type StructuredAgentSessionContinuationDeps = { clientMessageId: string ) => Promise /** Records a host-authored journal note: that this send was Orca's, not the user's, or that the - * chat did not carry on. `tone` is a display hint older clients render as plain text. */ + * chat did not carry on. `tone` is a display hint older clients render as plain text. Best + * effort, but a note that could not be written is reported: a swallowed append is how this + * regressed unnoticed once already. */ note: (sessionId: string, text: string, tone?: 'error' | 'warning') => Promise - /** Reports a note that could not be written. The note is best effort, but its failure is not - * allowed to be silent — a swallowed append is how this regressed unnoticed once already. */ - onNoteFailed: (sessionId: string, error: unknown) => void } /** A continuation handed to its agent, or already decided. */ @@ -232,7 +230,7 @@ export async function startStructuredAgentSessionContinuation( } async function noteOutcome( - deps: Pick, + deps: Pick, sessionId: string, result: StructuredAgentSessionContinuationOutcome ): Promise { @@ -242,7 +240,7 @@ async function noteOutcome( try { await deps.note(sessionId, AGENT_SESSION_RESTART_CONTINUATION_NOTE) } catch (error) { - deps.onNoteFailed(sessionId, error) + traceAgentSessionError({ step: 'restart-continuation-note', sessionId, error }) } } else { await noteNotContinued( @@ -260,7 +258,7 @@ async function noteOutcome( /** The chat itself carries the failure, so it survives the toast, a dismissed record and a restart, * and the user's next message is what moves past it. */ async function noteNotContinued( - deps: Pick, + deps: Pick, sessionId: string, outcome: 'refused' | 'not-connected' | 'unconfirmed' ): Promise { @@ -275,7 +273,7 @@ async function noteNotContinued( 'error' )) } catch (error) { - deps.onNoteFailed(sessionId, error) + traceAgentSessionError({ step: 'restart-continuation-note', sessionId, error }) } } @@ -295,7 +293,7 @@ async function sendContinuation( throw error } // Persistence can fail after dispatch; a thrown send is not proof of non-delivery. - console.warn('[structured-agent-session] restart continuation send failed') + traceAgentSessionError({ step: 'restart-continuation-send', sessionId, error }) return null }) if (!sent) { 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 ee769b9e8c33..1ed489f7f09f 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 @@ -31,6 +31,7 @@ import { type StructuredAgentSessionResumeOutcome } from './structured-agent-session-restart-resume-runner' import { RESTART_CONTINUATION_SUPERSEDED } from './structured-agent-session-restart-continuation' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' type FailureCapsule = Pick< AgentSessionRecoveryCapsule, @@ -86,9 +87,9 @@ export function createStructuredAgentSessionRestartFailureLedger(deps: { const read = async (): Promise => { try { return (await deps.capsule?.listFailed(deps.now())) ?? [] - } catch { + } catch (error) { // Recovery is advisory; a malformed capsule must not make ordinary chat actions unusable. - console.warn('[structured-agent-session] reading recovery capsule failed') + traceAgentSessionError({ step: 'recovery-capsule-read', error }) return [] } } @@ -175,23 +176,17 @@ export function createStructuredAgentSessionRestartFailureLedger(deps: { } await deps .enqueue(() => capsule.completeResume(operationId, completed, deps.now())) - .catch(() => { - console.warn('[structured-agent-session] restart offer completion failed') - }) + .catch((error: unknown) => traceAgentSessionError({ step: 'restart-offer-complete', error })) // Filed before the rollback so a failure the user must act on is never reopened as an offer // that would silently re-run it. await deps .enqueue(() => capsule.failResume(operationId, failures, deps.now())) - .catch(() => { - console.warn('[structured-agent-session] restart failure record failed') - }) + .catch((error: unknown) => traceAgentSessionError({ step: 'restart-failure-record', error })) // This only reopens rows still owned by this operation. Rows removed by completeResume stay // removed, even when the write of a later bookkeeping step fails. await deps .enqueue(() => capsule.rollbackResume(operationId, deps.now())) - .catch(() => { - console.warn('[structured-agent-session] restart offer rollback failed') - }) + .catch((error: unknown) => traceAgentSessionError({ step: 'restart-offer-rollback', error })) } return { diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-records.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-records.ts index f9530039cd4a..5f731d4a7736 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-records.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-records.ts @@ -3,6 +3,7 @@ import type { AgentSessionRecoveryCapsule } from '../../runtime/agent-session-recovery-capsule' import type { AgentSessionResumeMarker } from '../../../shared/agent-session-resume-marker' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionRestartOfferRecords = { /** Every pending offer. Read-only; nothing is spent. */ @@ -30,10 +31,10 @@ export function createStructuredAgentSessionRestartOfferRecords(deps: { const readMarkers = async (): Promise => { try { return (await deps.capsule?.list(deps.now())) ?? [] - } catch { + } catch (error) { // Recovery is advisory. A malformed capsule must not make ordinary chat actions unusable; // the durable bytes stay untouched so an explicit dismissal can remove them. - console.warn('[structured-agent-session] reading recovery capsule failed') + traceAgentSessionError({ step: 'recovery-capsule-read', error }) return [] } } @@ -68,9 +69,7 @@ export function createStructuredAgentSessionRestartOfferRecords(deps: { })) void deps .enqueue(() => capsule.forgetSuperseded(gone, deps.now())) - .catch(() => { - console.warn('[structured-agent-session] pruning superseded restart offers failed') - }) + .catch((error: unknown) => traceAgentSessionError({ step: 'restart-offer-prune', error })) } } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-withdrawal.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-withdrawal.ts index 76d8006d9a1a..aa3007ae7ba7 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-withdrawal.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-offer-withdrawal.ts @@ -13,6 +13,7 @@ import type { AgentSessionResumeMarker } from '../../../shared/agent-session-res import { isQueuedAgentJournalSubmission } from '../../../shared/agent-session-queued-submission' import type { StructuredAgentSessionHostSession } from './structured-agent-session-host-types' import { isRestartContinuationOf } from './structured-agent-session-restart-continuation-envelope' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type StructuredAgentSessionRestartOfferWithdrawal = ReturnType< typeof createStructuredAgentSessionRestartOfferWithdrawal @@ -84,9 +85,9 @@ export function createStructuredAgentSessionRestartOfferWithdrawal(deps: { startedFor === undefined ? false : isRestartContinuationOf(marker, startedFor) ) ) - .catch(() => { - console.warn('[structured-agent-session] withdrawing a restart offer failed') - }) + .catch((error: unknown) => + traceAgentSessionError({ step: 'restart-offer-withdraw', sessionId, error }) + ) } } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-ownership.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-ownership.test.ts index 59ff6958d53d..79d39c4a194f 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-ownership.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-ownership.test.ts @@ -69,7 +69,9 @@ it('reports a failed attribution note without an installed error sink or private const result = await host.restartResume.continueAfterRestart([SESSION], 'modal') expect(result.continued).toMatchObject([{ outcome: 'continued' }]) expect(warning).toHaveBeenCalledExactlyOnceWith( - '[structured-agent-session] restart continuation attribution failed' + '[agent-session] restart-continuation-note failed', + { sessionId: SESSION }, + 'Error' ) } finally { write.mockRestore() @@ -319,7 +321,8 @@ it('keeps concurrent recovery reads independent and non-destructive', async () = it('fails closed on corrupt recovery storage while an ordinary send still works', async () => { const { host, root, dispatch } = await interruptedRestart() - await writeFile(join(root, AGENT_SESSION_RECOVERY_CAPSULE_FILE), '{') + // Not JSON: its SyntaxError quotes the start of the file, which no log may repeat. + await writeFile(join(root, AGENT_SESSION_RECOVERY_CAPSULE_FILE), 'my private prompt text') const warning = vi.spyOn(console, 'warn').mockImplementation(() => {}) expect(await host.restartResume.list()).toEqual([]) expect(await host.restartResume.continueAfterRestart([SESSION], 'modal')).toEqual({ @@ -335,9 +338,14 @@ it('fails closed on corrupt recovery storage while an ordinary send still works' await vi.waitFor(() => expect(dispatch).toHaveBeenCalledTimes(1)) // list; the action's read of offers and of failures; the post-action refresh of both. The send // cannot withdraw an offer it cannot read either, and says so. - const withdrawing = '[structured-agent-session] withdrawing a restart offer failed' - await vi.waitFor(() => expect(warning).toHaveBeenLastCalledWith(withdrawing)) - expect(warning.mock.calls.filter(([message]) => message !== withdrawing)).toHaveLength(5) + const withdrawing = '[agent-session] restart-offer-withdraw failed' + await vi.waitFor(() => + expect(warning).toHaveBeenLastCalledWith(withdrawing, { sessionId: SESSION }, 'SyntaxError') + ) + expect(warning.mock.calls.filter(([message]) => message !== withdrawing)).toEqual( + Array.from({ length: 5 }, () => [expect.any(String), {}, 'SyntaxError']) + ) + expect(warning.mock.calls.flat().map(String).join(' ')).not.toContain('private') warning.mockRestore() }) @@ -451,7 +459,9 @@ it('logs teardown capsule publication failure and still releases the provider', 'agent_session_ownership_unknown' ) expect(warning).toHaveBeenCalledWith( - '[structured-agent-session] recording recovery capsule failed' + '[agent-session] recovery-capsule-record failed', + {}, + expect.any(String) ) expect(warning.mock.calls.flat().map(String).join(' ')).not.toContain(previous.root) expect(previous.store.getRecord(SESSION)?.lease.claimStatus).toBe('released') diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-host.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-host.ts index d053caf006b2..efd15f6d2bc8 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-host.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-host.ts @@ -44,6 +44,7 @@ import { import type { StructuredAgentSessionRestartResumeSurfaces } from './structured-agent-session-restart-resume-wiring' import { createStructuredAgentSessionRestartWitnesses } from './structured-agent-session-restart-witnesses' import { structuredAgentSessionConversationFence } from './structured-agent-session-provider-child' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' type LiveSession = StructuredAgentSessionRestartOfferSession @@ -205,9 +206,9 @@ export function createStructuredAgentSessionRestartResume( if (deps.recoveryCapsule) { await enqueueRecoveryOperation(() => deps.recoveryCapsule!.rollbackResume(operationId, surfaces.now()) - ).catch(() => { - console.warn('[structured-agent-session] restart offer rollback failed') - }) + ).catch((rollbackError: unknown) => + traceAgentSessionError({ step: 'restart-offer-rollback', error: rollbackError }) + ) } throw error } @@ -279,8 +280,8 @@ export function createStructuredAgentSessionRestartResume( try { remainingCandidates = await list() remainingFailures = await failures.list() - } catch { - console.warn('[structured-agent-session] restart offer refresh failed after action') + } catch (error) { + traceAgentSessionError({ step: 'restart-offer-refresh', error }) } return { resumed, diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-wiring.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-wiring.ts index 4004502e4081..7f05467be545 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-wiring.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-resume-wiring.ts @@ -29,7 +29,6 @@ export type StructuredAgentSessionRestartResumeSurfaces = { sessionId: string, clientMessageId: string ) => Promise<{ value: AgentSessionSendResult } | undefined> - onNoteFailed: (sessionId: string, error: unknown) => void now: () => number } @@ -76,8 +75,6 @@ export function structuredAgentSessionRestartResumeSurfaces( until: 'handed-over', budgetMs: MAX_TIMER_DELAY_MS }), - onNoteFailed: () => - console.warn('[structured-agent-session] restart continuation attribution failed'), now } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-teardown.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-teardown.test.ts index 2ea9e6f57b77..3ae9e98149a2 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restart-teardown.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restart-teardown.test.ts @@ -23,10 +23,14 @@ it.each(['beginTeardown', 'captureBeforeStop', 'recordMarkers'] as const)( await expect(host.flushAllStreamedEvents()).resolves.toBeUndefined() expect(operation).toHaveBeenCalledOnce() expect(warning).toHaveBeenCalledExactlyOnceWith( - { - beginTeardown: '[structured-agent-session] capturing recovery witnesses failed', - captureBeforeStop: '[structured-agent-session] capturing recovery witness failed', - recordMarkers: '[structured-agent-session] recording recovery capsule failed' + ...{ + beginTeardown: ['[agent-session] recovery-witness-begin failed', {}, 'Error'], + captureBeforeStop: [ + '[agent-session] recovery-witness-capture failed', + { sessionId: SESSION }, + 'Error' + ], + recordMarkers: ['[agent-session] recovery-capsule-record failed', {}, 'Error'] }[method] ) expect(warning.mock.calls.flat().map(String).join(' ')).not.toContain(failure.message) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-restore-without-import.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-restore-without-import.test.ts index 226e6536c9c1..0d519c56018a 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-restore-without-import.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-restore-without-import.test.ts @@ -216,7 +216,6 @@ type LifetimeHost = Parameters undefined, - onDeliveryError: () => undefined, now: () => clock }) } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.test.ts index fbe81be21ac1..f25ae7555520 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.test.ts @@ -25,6 +25,11 @@ import { resetHostTestOperationIds } from './structured-agent-session-host-test-data' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const CALLER = { callerKey: 'client-1' } @@ -39,12 +44,11 @@ let host: StructuredAgentSessionHost let acquire: Mock let spawnChild: StructuredAgentSessionAdapter['acquire'] let dispatch: Mock -let hostErrors: unknown[] beforeEach(async () => { root = await mkdtemp(join(tmpdir(), 'orca-send-recovery-')) resetHostTestOperationIds() - hostErrors = [] + vi.mocked(traceAgentSessionError).mockClear() let generation = 0 spawnChild = async ({ fence, spawnToken }) => ({ process: { hostId: 'local', pid: 4242, processStartTimeMs: 1_700_000_000_000, spawnToken }, @@ -84,8 +88,7 @@ beforeEach(async () => { journalDatabase: openTestJournalHostDatabase(root), claimKeyId: 'key-1', mintSpawnToken: () => `spawn-${acquire.mock.calls.length}`, - now: () => NOW, - onEventSinkError: ({ error }) => hostErrors.push(error) + now: () => NOW }) expect(await host.attach(CALLER, hostTestAttachParams(null))).toMatchObject({ ok: true }) }) @@ -407,7 +410,6 @@ describe('a send with no live owner', () => { acquire.mockRejectedValue( new CodexAppServerRequestError('thread/resume', -32600, `thread/resume failed: ${said}`, said) ) - const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) const id = await accept(sendParams('after the thread went away')) @@ -426,11 +428,11 @@ describe('a send with no live owner', () => { "Codex couldn't restart. Send your message to try again." ]) // Orca's own text is logged once where the start failed. - expect(warn).toHaveBeenCalledWith( - '[agent-session] provider start failed:', - expect.objectContaining({ message: `thread/resume failed: ${said}` }) - ) - warn.mockRestore() + expect(traceAgentSessionError).toHaveBeenCalledWith({ + step: 'provider-start', + sessionId: SESSION, + error: expect.objectContaining({ message: `thread/resume failed: ${said}` }) + }) }) it('restarts again for a Retry under a new id, and replays a resend of the same id', async () => { @@ -537,9 +539,11 @@ describe('a send with no live owner', () => { reason: "Orca ran into a problem, so this didn't go through. Try again.", rejection: { kind: 'hostFault' } }) - expect(hostErrors).toContainEqual( - expect.objectContaining({ message: 'spawn-token mint failed' }) - ) + expect(traceAgentSessionError).toHaveBeenCalledWith({ + step: 'delivery-loop', + sessionId: SESSION, + error: expect.objectContaining({ message: 'spawn-token mint failed' }) + }) expect(await errorStatuses()).toHaveLength(1) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.ts index be29089991bd..a3811b210f66 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-send-preparation.ts @@ -24,6 +24,7 @@ import { } from './structured-agent-session-mutation-admission' import { rewindRefusal } from './structured-rewind-refusal' import type { StructuredAgentSessionMutationContext } from './structured-agent-session-host-mutations' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' /** Why the record refuses any send right now, whoever owns it; null when a send may run. */ export function structuredAgentSessionSendBlock( @@ -64,7 +65,7 @@ export async function openConversationForWrite( } return { ok: false, refusal: AGENT_SESSION_NOT_ATTACHED } } catch (error) { - console.warn('[agent-session] opening the conversation for a write failed:', error) + traceAgentSessionError({ step: 'journal-open-write', sessionId: envelope.sessionId, error }) return { ok: false, refusal: journalOpenRefusal(error) } } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.test.ts index ad23177bdd3a..6e539abefc61 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.test.ts @@ -540,7 +540,7 @@ describe('StructuredAgentSessionStatusFeed', () => { const { feed } = feedFor(new Map([[SESSION, { journal }]]), null, (summary) => seen.push(summary.status) ) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) if (agent === 'claude') { const translator = createClaudeJournalTranslator({ sink: deferred.sink }) translator.handle({ diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.ts index 22a61a006bb6..0fe3838c95a4 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-status-feed.ts @@ -31,6 +31,7 @@ import { StructuredAgentSessionStatusOwnership, type StructuredAgentSessionStatusSink } from './structured-agent-session-status-ownership' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export type { StructuredAgentSessionStatusSink } from './structured-agent-session-status-ownership' @@ -182,7 +183,7 @@ export class StructuredAgentSessionStatusFeed { try { this.ownership.forget(sessionId) } catch (error) { - console.warn('[structured-session-status] status sink forget failed', error) + traceAgentSessionError({ step: 'status-forget', sessionId, error }) } } @@ -254,7 +255,7 @@ export class StructuredAgentSessionStatusFeed { this.deps.onStatusChanged?.(summary, { replay: options?.replay === true }) } catch (error) { // An observer must never cost the subscribers their status event. - console.warn('[structured-session-status] status observer failed', error) + traceAgentSessionError({ step: 'status-observer', sessionId, error }) } } @@ -306,7 +307,7 @@ export class StructuredAgentSessionStatusFeed { try { this.ownership.publishChildWork(sessionId, evidence, session.params.provider) } catch (error) { - console.warn('[structured-session-status] child work publish failed', error) + traceAgentSessionError({ step: 'child-work-publish', sessionId, error }) } } @@ -353,7 +354,7 @@ export class StructuredAgentSessionStatusFeed { try { this.ownership.publish(summary, location) } catch (error) { - console.warn('[structured-session-status] status sink publish failed', error) + traceAgentSessionError({ step: 'status-publish', sessionId: summary.sessionId, error }) } } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-subagent-recency.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-subagent-recency.test.ts index 20b5038f1734..ff6396b7f5cb 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-subagent-recency.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-subagent-recency.test.ts @@ -83,7 +83,7 @@ async function openSession() { }) const events: AgentSessionStatusEvent[] = [] feed.subscribe({ id: 'list-1', emit: (event) => events.push(event) }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) deferred.bind({ journal, fence: 1, publish: () => feed.publish(SESSION, journal) }) const drain = async (): Promise => { expect(await deferred.drained()).toEqual({ ok: true }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-surface-lifetime.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-surface-lifetime.test.ts index a06c70bf30ad..50d6f3f0c2b5 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-surface-lifetime.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-surface-lifetime.test.ts @@ -41,6 +41,11 @@ import { import { agentSessionFailureFact } from '../../../shared/agent-session-failure' import { agentSessionFailureWords } from '../../../shared/agent-session-failure-words' import { openTestJournalHostDatabase } from '../agent-session-journal/journal-host-database-test-support' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const UNEXPECTED_PROVIDER_EXIT_OUTCOME = 'Codex stopped while this response was in progress. You can continue in this conversation.' @@ -83,7 +88,6 @@ function openHost( mintSpawnToken: () => `spawn-${acquire.mock.calls.length}`, idleSweep: { intervalMs: SWEEP_MS, idleMs: IDLE_MS }, now: () => clock, - onEventSinkError: ({ error }) => hostErrors.push(error), statusSink, ...(probeOwner ? { probeOwner } : {}) }) @@ -206,6 +210,9 @@ beforeEach(async () => { resetHostTestOperationIds() sink = null hostErrors = [] + vi.mocked(traceAgentSessionError).mockImplementation(({ error }) => { + hostErrors.push(error) + }) clock = NOW statusSink = { publish: vi.fn(), forget: vi.fn() } let generation = 0 @@ -332,6 +339,32 @@ describe('a chat that closes', () => { expect(closeSession).toHaveBeenCalledOnce() }) + it('records a failed stop-time settlement once, and still throws it as the cause', async () => { + await attach() + emitTurnLifecycle('running', 1) + await host.flushStreamedEvents(SESSION) + const refusal = new Error('settlement unavailable') + const refusing = vi + .spyOn(host['sessions'].get(SESSION)!.journal, 'appendLifecycleBatch') + .mockRejectedValue(refusal) + vi.mocked(traceAgentSessionError).mockClear() + + const thrown: unknown = await host.close(SESSION).catch((error: unknown) => error) + + expect(thrown).toMatchObject({ step: 'settle-dead-generation' }) + const wrapper = thrown instanceof Error ? thrown.cause : undefined + expect(wrapper).toMatchObject({ message: 'dead generation work settlement failed' }) + expect(wrapper instanceof Error ? wrapper.cause : undefined).toBe(refusal) + expect( + vi + .mocked(traceAgentSessionError) + .mock.calls.filter(([report]) => report.step === 'dead-generation-settlement') + ).toEqual([[{ step: 'dead-generation-settlement', sessionId: SESSION, error: refusal }]]) + + refusing.mockRestore() + await expect(host.close(SESSION)).resolves.toBeUndefined() + }) + it('settles and releases on the retry when a step after the child stopped aborts', async () => { await attach() dispatch.mockResolvedValueOnce({ state: 'admitted' }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-turns.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-turns.ts index 13aa9d72aea0..b262d6016f2d 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-turns.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-turns.ts @@ -23,6 +23,7 @@ import { } from '../../../shared/agent-session-wire' import { isAgentSessionRefusalError } from '../../../shared/agent-session-wire-refusals' import { DISPATCH_DOUBT_PERSISTENCE_FAILED } from '../agent-session-journal/journal-dispatch-doubt-reasons' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' import type { AgentSessionJournal } from '../agent-session-journal/journal-store' import type { AgentSessionDispatchOutcome, @@ -238,8 +239,13 @@ export async function handOverSubmission( reason: DISPATCH_DOUBT_PERSISTENCE_FAILED, fence: ctx.fence }) - } catch { - // Nothing further to record; the pending row is settled on the next open. + } catch (doubtError) { + // The pending row is settled on the next open. + traceAgentSessionError({ + step: 'dispatch-doubt-record', + sessionId: ctx.sessionId, + error: doubtError + }) } throw error } diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.test.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.test.ts index 2cb38a466345..9312f362a1ff 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.test.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.test.ts @@ -13,6 +13,11 @@ import { type StructuredAgentSessionUnexpectedExitContext, type StructuredAgentSessionUnexpectedExitSession } from './structured-agent-session-unexpected-exit' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' + +vi.mock('../../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const exitOutcome = (agent: string): string => `${agent} stopped while this response was in progress. You can continue in this conversation.` @@ -406,7 +411,7 @@ describe('provider-exit settlement', () => { }) } } - const release = vi.fn() + vi.mocked(traceAgentSessionError).mockClear() const publishFence = vi.fn() const event = { type: 'ended' as const, @@ -423,13 +428,15 @@ describe('provider-exit settlement', () => { flushLifecycle: async () => ({ ok: false, error: new Error('sink failed') }), publishFence, serialize: async (_sessionId, task) => task(), - now: () => 1, - onBarrierError: release + now: () => 1 } await settleUnexpectedStructuredAgentSessionExit(context, event) expect(session.child).toBeNull() expect(publishFence).toHaveBeenCalledTimes(1) - expect(release).toHaveBeenCalledTimes(2) + expect(vi.mocked(traceAgentSessionError).mock.calls.map(([report]) => report.step)).toEqual([ + 'provider-exit-barrier', + 'dead-generation-settlement' + ]) }) }) diff --git a/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.ts b/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.ts index 3f758f81607b..f625889ea5e7 100644 --- a/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.ts +++ b/src/main/native-chat/agent-session-wire/structured-agent-session-unexpected-exit.ts @@ -14,9 +14,14 @@ import { MAX_UNEXPECTED_EXIT_REASON_CHARS, settleStructuredAgentSessionDeadGeneration, type DeadGenerationJournal, + type StructuredAgentSessionDeadGenerationSettlement, unfinishedStructuredAgentSessionWorkWasInterrupted } from './structured-agent-session-dead-generation-settlement' import type { StructuredAgentSessionTurnVerdict } from './structured-agent-session-stale-turn-verdict' +import { + traceAgentSessionError, + type AgentSessionErrorStep +} from '../../observability/agent-session-error-trace' type UnexpectedExitLifecycleEvent = StructuredAgentSessionEndedEvent & { cause: 'unexpected-exit' @@ -37,7 +42,6 @@ export type StructuredAgentSessionUnexpectedExitContext< publishStatus?: (sessionId: string) => void serialize: (sessionId: string, task: () => Promise) => Promise now: () => number - onBarrierError?: (sessionId: string, error: unknown) => void } export async function settleUnexpectedStructuredAgentSessionExit< @@ -87,19 +91,20 @@ export async function settleUnexpectedStructuredAgentSessionExit< return } + const reportExitFailure = (step: AgentSessionErrorStep, error: unknown): void => + traceAgentSessionError({ step, sessionId: unexpectedEvent.sessionId, error }) const stableSettlementId = providerExitSettlementId(unexpectedEvent) const unfinishedWork = captureUnfinishedStructuredAgentSessionWork(session.journal) try { try { const barrier = await context.flushLifecycle(unexpectedEvent.sessionId) if (!barrier.ok) { - context.onBarrierError?.(unexpectedEvent.sessionId, barrier.error) + reportExitFailure('provider-exit-barrier', barrier.error) } } catch (error) { - context.onBarrierError?.(unexpectedEvent.sessionId, error) + reportExitFailure('provider-exit-barrier', error) } await retryUnexpectedExitSettlement({ - context, event: unexpectedEvent, journal: session.journal, fence: child.fence, @@ -136,7 +141,7 @@ export async function settleUnexpectedStructuredAgentSessionExit< exitReason: unexpectedEvent.reason.slice(0, MAX_UNEXPECTED_EXIT_REASON_CHARS) }) } catch (error) { - context.onBarrierError?.(unexpectedEvent.sessionId, error) + reportExitFailure('provider-exit-lease-release', error) } finally { endChild() if (released) { @@ -148,7 +153,6 @@ export async function settleUnexpectedStructuredAgentSessionExit< } async function retryUnexpectedExitSettlement(input: { - context: Pick event: UnexpectedExitLifecycleEvent journal: DeadGenerationJournal fence: number @@ -157,7 +161,7 @@ async function retryUnexpectedExitSettlement(input: { exitedDuringStartup: boolean failureTextContext: AgentSessionFailureWordsContext showUnexpectedExitOutcome?: boolean -}): Promise { +}): Promise { return settleStructuredAgentSessionDeadGeneration({ journal: input.journal, sessionId: input.event.sessionId, @@ -170,8 +174,7 @@ async function retryUnexpectedExitSettlement(input: { failureTextContext: input.failureTextContext, ...(input.exitedDuringStartup ? { exitedDuringStartup: { generation: input.event.acquisitionGeneration } } - : {}), - onError: input.context.onBarrierError + : {}) }) } diff --git a/src/main/native-chat/agent-session-wire/structured-rewind-recovery.ts b/src/main/native-chat/agent-session-wire/structured-rewind-recovery.ts index b572e51e5f39..0050f6bb6628 100644 --- a/src/main/native-chat/agent-session-wire/structured-rewind-recovery.ts +++ b/src/main/native-chat/agent-session-wire/structured-rewind-recovery.ts @@ -13,6 +13,7 @@ import type { AgentSessionJournal } from '../agent-session-journal/journal-store import type { StructuredAgentSessionAdapter } from './structured-agent-session-adapter' import { AGENT_SESSION_HISTORY_MAX_PAGE_BYTES } from './agent-session-history-page-bounds' import { rewindRefusal } from './structured-rewind-refusal' +import { traceAgentSessionError } from '../../observability/agent-session-error-trace' export function persistRewindRecord( store: AgentSessionRecordStore, @@ -52,10 +53,11 @@ async function settleUnsupportedClaudeRewind( outcome: { status: 'failed', code: refusal.code, rewindReason: 'unsupported' } }) } catch (error) { - console.warn('[structured-rewind] pending Claude rewind was not settled:', { + traceAgentSessionError({ + step: 'rewind-recovery', sessionId, - operationId: rewind.operationId, - error + error, + detail: { operationId: rewind.operationId } }) } } diff --git a/src/main/observability/agent-session-error-trace-ratchet.test.ts b/src/main/observability/agent-session-error-trace-ratchet.test.ts new file mode 100644 index 000000000000..348904a50c32 --- /dev/null +++ b/src/main/observability/agent-session-error-trace-ratchet.test.ts @@ -0,0 +1,130 @@ +import { readFileSync, readdirSync, statSync } from 'node:fs' +import { basename, join, relative, resolve } from 'node:path' +import { describe, expect, it } from 'vitest' + +/** + * Structured chat session code reports every background error through + * `traceAgentSessionError`. The two shapes it replaced both lost failures in a packaged + * build: a `console` line (the main process owns no console there) and an optional `on*Error?` sink + * that no caller had to supply. A catch site reports its own step; a callback it takes carries + * behavior and is required. + */ +const REPO_ROOT = resolve(__dirname, '..', '..', '..') + +/** Directories scanned whole. */ +const SCANNED_TREES = [ + 'src/main/native-chat/agent-session-wire', + 'src/main/native-chat/agent-session-journal', + 'src/main/native-chat/agent-model-catalog' +] +/** Directories whose files with one of these prefixes are scanned. */ +const SCANNED_PREFIXED: readonly { dir: string; prefix: string }[] = [ + { dir: 'src/main/native-chat', prefix: 'structured-agent-session-' }, + { dir: 'src/main/runtime', prefix: 'structured-agent-session-' }, + { dir: 'src/main/runtime/rpc/methods', prefix: 'structured-agent-session-' }, + { dir: 'src/main/claude', prefix: 'claude-structured-' } +] + +const CONSOLE_FAILURE = + /\bconsole\s*(?:\.\s*(?:warn|error)|\[\s*(['"`])(?:warn|error)\1\s*\])(?![\w$])/ +const OPTIONAL_ERROR_SINK = /\b(on\w*(?:Error|Failure|Failed))\s*\?\s*[:(]/g + +/** Optional because they carry behavior only some callers want, never because a caller may skip + * reporting: each failure is also reported, or handled, where it happens. */ +const BEHAVIORAL_OPTIONAL_CALLBACKS = new Set([ + // Hands agent-start the acquisition error its refusal is built from; attach-flow reports it too. + 'onAcquisitionFailed', + // Rejects the start or ends the child; a translator built outside an acquisition has neither. + 'onBackgroundTaskJournalFailure' +]) + +function isProductionSource(path: string): boolean { + return /\.tsx?$/.test(path) && !/\.(?:test|spec)\.tsx?$/.test(path) +} + +function collectTree(root: string): string[] { + return readdirSync(root).flatMap((entry) => { + const full = join(root, entry) + return statSync(full).isDirectory() ? collectTree(full) : [full] + }) +} + +function scannedFiles(): string[] { + const trees = SCANNED_TREES.flatMap((dir) => collectTree(join(REPO_ROOT, dir))) + const prefixed = SCANNED_PREFIXED.flatMap(({ dir, prefix }) => + readdirSync(join(REPO_ROOT, dir)) + .filter((entry) => entry.startsWith(prefix)) + .map((entry) => join(REPO_ROOT, dir, entry)) + .filter((full) => statSync(full).isFile()) + ) + return [...trees, ...prefixed].filter((full) => isProductionSource(basename(full))) +} + +/** Drop comment-only lines so prose about the old idiom is not an offender. */ +function codeText(contents: string): string { + return contents + .split('\n') + .filter((line) => !/^\s*(?:\/\/|\/\*|\*)/.test(line)) + .join('\n') +} + +function repoPath(file: string): string { + return relative(REPO_ROOT, file).split('\\').join('/') +} + +function consoleOffenders(files: readonly string[]): string[] { + return files + .filter((file) => CONSOLE_FAILURE.test(codeText(readFileSync(file, 'utf8')))) + .map(repoPath) +} + +function optionalSinks(text: string): string[] { + return [...text.matchAll(OPTIONAL_ERROR_SINK)] + .map((match) => match[1]) + .filter((name) => !BEHAVIORAL_OPTIONAL_CALLBACKS.has(name)) +} + +function optionalSinkOffenders(files: readonly string[]): string[] { + return files.flatMap((file) => + optionalSinks(codeText(readFileSync(file, 'utf8'))).map((name) => `${repoPath(file)}: ${name}`) + ) +} + +describe('structured chat session background error reporting', () => { + const files = scannedFiles() + + it('scans a plausible number of files', () => { + // A moved directory would make the guard silently vacuous. + expect(files.length).toBeGreaterThan(250) + }) + + it('reports failures through the reporter, never the console', () => { + expect( + consoleOffenders(files), + 'Call traceAgentSessionError from src/main/observability/agent-session-error-trace instead.' + ).toEqual([]) + }) + + it('declares no optional error sink', () => { + expect( + optionalSinkOffenders(files), + 'Report at the catch site; a callback that carries behavior is required.' + ).toEqual([]) + }) + + it('catches both shapes', () => { + expect(CONSOLE_FAILURE.test("console.warn('x', error)")).toBe(true) + expect(CONSOLE_FAILURE.test("console['error']('x')")).toBe(true) + expect(CONSOLE_FAILURE.test('const warn = console.warn')).toBe(true) + expect(CONSOLE_FAILURE.test("console.info('x')")).toBe(false) + expect(CONSOLE_FAILURE.test('console.warning')).toBe(false) + expect(optionalSinks(' onError?: (error: unknown) => void')).toEqual(['onError']) + expect(optionalSinks(' onEventSinkError?: (input) => void')).toEqual(['onEventSinkError']) + expect(optionalSinks(' onFailure?: (error: unknown) => void')).toEqual(['onFailure']) + expect(optionalSinks(' onNoteFailed?(error: unknown): void')).toEqual(['onNoteFailed']) + expect(optionalSinks(' onAcquisitionFailed?: (error: unknown) => void')).toEqual([]) + expect(optionalSinks(' onError: (error: unknown) => void')).toEqual([]) + expect(optionalSinks(' deps.onError?.(error)')).toEqual([]) + expect(optionalSinks(' const x = onFailure ? a : b')).toEqual([]) + }) +}) diff --git a/src/main/observability/agent-session-error-trace.test.ts b/src/main/observability/agent-session-error-trace.test.ts new file mode 100644 index 000000000000..bc7853b3f43d --- /dev/null +++ b/src/main/observability/agent-session-error-trace.test.ts @@ -0,0 +1,256 @@ +import { mkdtempSync, readFileSync, rmSync } from 'node:fs' +import { tmpdir } from 'node:os' +import { join } from 'node:path' +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest' +import { + AGENT_SESSION_ERROR_STEPS, + traceAgentSessionError, + type AgentSessionErrorStep +} from './agent-session-error-trace' +import { createLocalFileSink } from './local-file-sink' +import { setActiveSink } from './tracer' + +let dir: string + +beforeEach(() => { + dir = mkdtempSync(join(tmpdir(), 'orca-agent-session-failure-')) +}) + +afterEach(() => { + setActiveSink(null) + vi.restoreAllMocks() + rmSync(dir, { recursive: true, force: true }) +}) + +function isRecord(value: unknown): value is Record { + return typeof value === 'object' && value !== null && !Array.isArray(value) +} + +function readTrace(filePath: string): Record[] { + return readFileSync(filePath, 'utf8') + .split('\n') + .filter(Boolean) + .map((line) => { + const record: unknown = JSON.parse(line) + if (!isRecord(record)) { + throw new Error(`trace line is not an object: ${line}`) + } + return record + }) +} + +function failureCause(record: Record | undefined): string { + const exit = record?.exit + if (!isRecord(exit) || typeof exit.cause !== 'string') { + throw new Error('trace record has no failure cause') + } + return exit.cause +} + +describe('traceAgentSessionError', () => { + it('writes a failed span with its step and session to the trace file', () => { + vi.spyOn(console, 'warn').mockImplementation(() => {}) + const filePath = join(dir, 'logs', 'main.trace.ndjson') + const sink = createLocalFileSink({ filePath, flushBufferThreshold: 1 }) + setActiveSink(sink) + + traceAgentSessionError({ + step: 'lease-renewal', + sessionId: 'session-1', + error: new Error('dead generation work settlement failed', { + cause: new AggregateError([new Error('journal write refused')], 'settle failed') + }), + detail: { fence: 3 } + }) + sink.flush() + sink.close() + + const records = readTrace(filePath) + expect(records).toEqual([ + expect.objectContaining({ + type: 'effect-span', + name: 'agent-session.failure', + attributes: { step: 'lease-renewal', sessionId: 'session-1', fence: 3 }, + exit: { _tag: 'Failure', cause: expect.any(String) } + }) + ]) + const cause = failureCause(records[0]) + // The wrapper alone names only the step; the chain is what says why. + expect(cause).toContain('dead generation work settlement failed') + expect(cause).toContain('[cause] AggregateError: settle failed') + expect(cause).toContain('[aggregated] Error: journal write refused') + }) + + it('records a non-Error failure as its text', () => { + vi.spyOn(console, 'warn').mockImplementation(() => {}) + const filePath = join(dir, 'main.trace.ndjson') + const sink = createLocalFileSink({ filePath, flushBufferThreshold: 1 }) + setActiveSink(sink) + + traceAgentSessionError({ step: 'journal-rollback', error: 'database is locked' }) + sink.flush() + sink.close() + + expect(readTrace(filePath)).toEqual([ + expect.objectContaining({ + attributes: { step: 'journal-rollback' }, + exit: { _tag: 'Failure', cause: 'database is locked' } + }) + ]) + }) + + it('keeps a SQLite or journal code the message leaves out', () => { + vi.spyOn(console, 'warn').mockImplementation(() => {}) + const filePath = join(dir, 'main.trace.ndjson') + const sink = createLocalFileSink({ filePath, flushBufferThreshold: 1 }) + setActiveSink(sink) + const error = Object.assign(new Error('database or disk is full'), { code: 'SQLITE_FULL' }) + + traceAgentSessionError({ step: 'journal-rollback', error }) + sink.flush() + sink.close() + + const cause = failureCause(readTrace(filePath)[0]) + expect(cause).toContain('database or disk is full') + expect(cause).toContain('[code] SQLITE_FULL') + }) + + it('keeps its own step and session over same-named detail keys', () => { + const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const filePath = join(dir, 'main.trace.ndjson') + const sink = createLocalFileSink({ filePath, flushBufferThreshold: 1 }) + setActiveSink(sink) + + traceAgentSessionError({ + step: 'idle-sweep', + sessionId: 'session-1', + error: 'x', + detail: { step: 'forged', sessionId: 'session-2', fence: 3 } + }) + sink.flush() + sink.close() + + expect(readTrace(filePath)[0].attributes).toEqual({ + step: 'idle-sweep', + sessionId: 'session-1', + fence: 3 + }) + expect(warn).toHaveBeenCalledWith( + '[agent-session] idle-sweep failed', + { sessionId: 'session-1', fence: 3, step: 'forged' }, + 'x' + ) + }) + + // Reclassifying a step edits this list, next to the reason in the step table. + const kindOnlySteps: readonly AgentSessionErrorStep[] = [ + 'operation-uncertainty-persist', + 'refused-operation-settlement', + 'recovery-capsule-read', + 'recovery-capsule-record', + 'recovery-witness-begin', + 'recovery-witness-capture', + 'recovery-records-forget', + 'restart-offer-prune', + 'restart-offer-withdraw', + 'restart-offer-complete', + 'restart-offer-rollback', + 'restart-offer-refresh', + 'restart-failure-record', + 'restart-continuation-send', + 'restart-continuation-note' + ] + + it('keeps exactly the pinned steps to the error kind', () => { + const tableKindSteps = Object.entries(AGENT_SESSION_ERROR_STEPS) + .filter(([, recorded]) => recorded === 'kind') + .map(([step]) => step) + expect(tableKindSteps.sort()).toEqual([...kindOnlySteps].sort()) + }) + + it.each(kindOnlySteps)('keeps %s to the error kind, in the trace and on the console', (step) => { + const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const filePath = join(dir, 'main.trace.ndjson') + const sink = createLocalFileSink({ filePath, flushBufferThreshold: 1 }) + setActiveSink(sink) + // What a corrupt capsule's parse throws: V8 quotes the input's first 10 characters. + const quoting = syntaxErrorQuoting('my private words') + expect(String(quoting)).toContain('my private') + const error = new Error('outer', { cause: quoting }) + + traceAgentSessionError({ step, sessionId: 'session-1', error }) + sink.flush() + sink.close() + + expect(readFileSync(filePath, 'utf8')).not.toContain('my private') + expect(readTrace(filePath)).toEqual([ + expect.objectContaining({ exit: { _tag: 'Failure', cause: 'Error' } }) + ]) + expect(warn).toHaveBeenCalledExactlyOnceWith( + `[agent-session] ${step} failed`, + { sessionId: 'session-1' }, + 'Error' + ) + }) + + it('keeps a recovery step to the error kind, in the trace and on the console', () => { + const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const filePath = join(dir, 'main.trace.ndjson') + const sink = createLocalFileSink({ filePath, flushBufferThreshold: 1 }) + setActiveSink(sink) + const error = Object.assign(new Error('latest prompt: "my private words"'), { code: 'EISDIR' }) + + traceAgentSessionError({ step: 'recovery-capsule-record', error }) + sink.flush() + sink.close() + + expect(readTrace(filePath)).toEqual([ + expect.objectContaining({ exit: { _tag: 'Failure', cause: 'Error EISDIR' } }) + ]) + expect(warn).toHaveBeenCalledExactlyOnceWith( + '[agent-session] recovery-capsule-record failed', + {}, + 'Error EISDIR' + ) + }) + + it('still writes the console line with no trace sink installed', () => { + const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + const error = new Error('boom') + + traceAgentSessionError({ step: 'idle-sweep', sessionId: 'session-1', error }) + + expect(warn).toHaveBeenCalledWith( + '[agent-session] idle-sweep failed', + { sessionId: 'session-1' }, + error + ) + }) + + it('never throws, whatever the sink or the console does', () => { + const warn = vi.spyOn(console, 'warn').mockImplementation(() => { + throw new Error('console gone') + }) + setActiveSink({ + push: () => { + throw new Error('disk full') + }, + flush: () => {}, + close: () => {} + }) + + expect(() => + traceAgentSessionError({ step: 'event-sink', sessionId: 'session-1', error: 'x' }) + ).not.toThrow() + expect(warn).toHaveBeenCalledTimes(1) + }) +}) + +function syntaxErrorQuoting(text: string): unknown { + try { + JSON.parse(text) + } catch (error) { + return error + } + throw new Error('expected a SyntaxError') +} diff --git a/src/main/observability/agent-session-error-trace.ts b/src/main/observability/agent-session-error-trace.ts new file mode 100644 index 000000000000..1fd246b36b80 --- /dev/null +++ b/src/main/observability/agent-session-error-trace.ts @@ -0,0 +1,170 @@ +// Where a structured chat session's background errors go: failures a catch site swallows or +// settles itself, so no caller ever sees them. Every such site reports here with its own step, so +// none depends on a caller having wired a sink: the trace file is installed once at startup, and +// the diagnostic bundle ships it. The console line is the only record where no trace sink is +// installed (dev runs, orcad, diagnostics disabled); a packaged desktop main process owns no console. + +import { startSpan } from './tracer' + +/** + * Every step, and what its trace record and console line may carry: `full` records the error's + * stack and cause chain; `kind` records only its class and code. The trace redactor strips + * credentials, not prose or paths, so a step whose error can quote user content must be `kind`. + * The recovery capsule steps are, because a corrupt capsule fails `JSON.parse` in + * agent-session-recovery-capsule-entries.ts, and a SyntaxError message quotes the capsule's text. + * The operation-settlement and restart-continuation steps are because the restart privacy tests + * pin that their errors never reach a log. + */ +export const AGENT_SESSION_ERROR_STEPS = { + // Provider lifecycle delivered to the host. + 'provider-started-settlement': 'full', + 'provider-exit-settlement': 'full', + 'provider-exit-barrier': 'full', + 'provider-exit-lease-release': 'full', + 'provider-start': 'full', + 'started-options-persist': 'full', + 'late-dispatch-settlement': 'full', + 'unanswered-dispatch-release': 'full', + 'dead-generation-settlement': 'full', + 'sink-failure-recovery': 'full', + 'operation-agent-start': 'full', + // Chat creation, before and after it commits. + 'create-precommit': 'full', + 'create-tab-publish': 'full', + // Claude's side of a session. + 'claude-attachment-read': 'full', + 'claude-dispatch-write': 'full', + 'claude-history-window': 'full', + 'claude-option-restore': 'full', + 'claude-resume-point-persist': 'full', + 'claude-exit-cursor-persist': 'full', + // The journal and what writes through it. + 'event-sink': 'full', + 'journal-delivery': 'full', + 'journal-database-open': 'full', + 'journal-open-read': 'full', + 'journal-open-write': 'full', + 'journal-open-pending-doubt': 'full', + 'journal-rollback': 'full', + 'journal-row-bookkeeping': 'full', + 'legacy-journal-import': 'full', + 'legacy-journal-retire': 'full', + 'gone-generation-settlement': 'full', + 'death-evidence-resettle': 'full', + 'restart-reconciliation': 'full', + 'dispatch-doubt-record': 'full', + // Leases. + 'lease-probe': 'full', + 'lease-renewal': 'full', + // Delivery, queued drafts and Stop. + 'delivery-wake': 'full', + 'delivery-loop': 'full', + 'delivery-loop-failure-settlement': 'full', + 'idle-sweep': 'full', + 'queued-drain': 'full', + 'queued-send-failure-hold': 'full', + 'queued-owed-settlement': 'full', + 'queued-repair': 'full', + 'queued-abandon': 'full', + 'queue-pause-retire': 'full', + 'clear-draft-carry': 'full', + 'stop-owed-settlement': 'full', + 'stop-queue-pause': 'full', + 'operation-uncertainty-persist': 'kind', + 'refused-operation-settlement': 'kind', + 'rewind-recovery': 'full', + // Status projection. + 'status-publish': 'full', + 'status-forget': 'full', + 'status-observer': 'full', + 'child-work-publish': 'full', + // Restart recovery. + 'recovery-capsule-read': 'kind', + 'recovery-capsule-record': 'kind', + 'recovery-witness-begin': 'kind', + 'recovery-witness-capture': 'kind', + 'recovery-records-forget': 'kind', + 'restart-offer-prune': 'kind', + 'restart-offer-withdraw': 'kind', + 'restart-offer-complete': 'kind', + 'restart-offer-rollback': 'kind', + 'restart-offer-refresh': 'kind', + 'restart-failure-record': 'kind', + 'restart-continuation-send': 'kind', + 'restart-continuation-note': 'kind', + // Chat tabs. + 'tab-visibility-restore': 'full', + 'worker-tab-retire': 'full' +} as const satisfies Record + +/** Closed so trace readers can rely on the vocabulary; add a step above with its catch site. */ +export type AgentSessionErrorStep = keyof typeof AGENT_SESSION_ERROR_STEPS + +export type AgentSessionErrorReport = { + step: AgentSessionErrorStep + sessionId?: string + error: unknown + /** Ids and closed-vocabulary facts only; attributes pass through the trace redactor. */ + detail?: Record +} + +const SPAN_NAME = 'agent-session.failure' +const MAX_CAUSE_DEPTH = 5 +const MAX_AGGREGATE_ERRORS = 10 + +/** Never throws: reporting is bookkeeping and must not replace the failure it describes. */ +export function traceAgentSessionError(report: AgentSessionErrorReport): void { + const { step, sessionId, error, detail } = report + const kindOnly = AGENT_SESSION_ERROR_STEPS[step] === 'kind' + // The report's own step and session win over a same-named detail key. + const context = { ...detail, ...(sessionId === undefined ? {} : { sessionId }) } + try { + startSpan(SPAN_NAME, { attributes: { ...context, step } }).fail( + kindOnly ? errorKind(error) : describeFailure(error) + ) + } catch { + // The console line below still carries it. + } + try { + console.warn(`[agent-session] ${step} failed`, context, kindOnly ? errorKind(error) : error) + } catch { + // Nothing left to tell. + } +} + +/** The whole chain: a wrapper's message alone names the step and nothing else. */ +function describeFailure(error: unknown, depth = 0): string { + if (!(error instanceof Error)) { + return String(error) + } + const code = errorCode(error) + // `code` (SQLITE_*, journal_*) is often the only part the message leaves out. + const head = `${error.stack ?? `${error.name}: ${error.message}`}${code === undefined ? '' : `\n[code] ${code}`}` + if (depth >= MAX_CAUSE_DEPTH) { + return head + } + const parts = [head] + if (error instanceof AggregateError) { + for (const inner of error.errors.slice(0, MAX_AGGREGATE_ERRORS)) { + parts.push(`[aggregated] ${describeFailure(inner, depth + 1)}`) + } + } + if (error.cause !== undefined) { + parts.push(`[cause] ${describeFailure(error.cause, depth + 1)}`) + } + return parts.join('\n') +} + +/** What failed, without anything it said: its class and, for system errors, its code. */ +function errorKind(error: unknown): string { + if (!(error instanceof Error)) { + return typeof error + } + const code = errorCode(error) + return code === undefined ? error.name : `${error.name} ${code}` +} + +function errorCode(error: Error): string | number | undefined { + const code = 'code' in error ? error.code : undefined + return typeof code === 'string' || typeof code === 'number' ? code : undefined +} diff --git a/src/main/runtime/rpc/methods/structured-agent-session-at-rest.test.ts b/src/main/runtime/rpc/methods/structured-agent-session-at-rest.test.ts index 9cbad804cd50..db2e820c5f37 100644 --- a/src/main/runtime/rpc/methods/structured-agent-session-at-rest.test.ts +++ b/src/main/runtime/rpc/methods/structured-agent-session-at-rest.test.ts @@ -287,8 +287,8 @@ describe('the accessor', () => { const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) const logged = (): unknown[] => warn.mock.calls - .filter(([line]) => line === '[agent-session] opening the conversation for a read failed:') - .map(([, error]) => error) + .filter(([line]) => line === '[agent-session] journal-open-read failed') + .map(([, , error]) => error) const reconnect = async (): Promise => [ ...(await call('agentSession.subscribe', { sessionId: SESSION })), ...(await call('agentSession.history', { sessionId: SESSION, direction: 'tail' })) 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 0c3b7b087133..b45053ba2672 100644 --- a/src/main/runtime/rpc/methods/structured-agent-session-create.ts +++ b/src/main/runtime/rpc/methods/structured-agent-session-create.ts @@ -27,6 +27,7 @@ import type { StructuredAgentSessionHost } from '../../../native-chat/agent-sess import type { StructuredAgentSessionCaller } from '../../../native-chat/agent-session-wire/structured-agent-session-host-types' import type { StructuredAgentSessionResumeSource } from '../../../../shared/structured-agent-session-create' import type { OrcaRuntimeService } from '../../orca-runtime' +import { traceAgentSessionError } from '../../../observability/agent-session-error-trace' import { resolveUncommittedStructuredCreate, type StructuredCreateRefused @@ -142,7 +143,7 @@ export async function commitStructuredAgentSessionCreate(args: { ...(surfaceTabId ? { tabId: surfaceTabId } : {}) }) } catch (error) { - console.warn('[agent-session] create committed before tab publication failed', error) + traceAgentSessionError({ step: 'create-tab-publish', sessionId: result.value.sessionId, error }) return { ok: false, refusal: refuse( 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..85c542c3206c 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 { traceAgentSessionError } from '../../../observability/agent-session-error-trace' export type StructuredCreateRefused = { refusal: AgentSessionWireRefusal } @@ -56,8 +57,8 @@ 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) + // moving, the trace keeps the cause findable. Nothing names its situation, so it carries no reason. + traceAgentSessionError({ step: 'create-precommit', error }) return refuseUnclassified( UNCODED_PRECOMMIT_REFUSAL_CODE, `Orca could not prepare a structured agent chat for this workspace: ${message}` diff --git a/src/main/runtime/structured-agent-session-close.ts b/src/main/runtime/structured-agent-session-close.ts index 668b7f218903..ad626236a482 100644 --- a/src/main/runtime/structured-agent-session-close.ts +++ b/src/main/runtime/structured-agent-session-close.ts @@ -19,6 +19,7 @@ import { observeStructuredWorker, structuredSessionCloseSettled } from './structured-worker-authority' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' export type StructuredAgentSessionCloseOutcome = { stopped: boolean @@ -146,9 +147,6 @@ async function restorePersistedTabVisibility( try { await host.setSessionTabVisibility?.(sessionId, true, tabId) } catch (error) { - console.warn( - `[structured-session-close] could not restore the chat tab for ${sessionId} after a failed close`, - error - ) + traceAgentSessionError({ step: 'tab-visibility-restore', sessionId, error }) } } diff --git a/src/main/runtime/structured-agent-session-host-refusal.test.ts b/src/main/runtime/structured-agent-session-host-refusal.test.ts index 689ac3df969c..1fff0669e029 100644 --- a/src/main/runtime/structured-agent-session-host-refusal.test.ts +++ b/src/main/runtime/structured-agent-session-host-refusal.test.ts @@ -25,6 +25,11 @@ import { ensureStructuredAgentSessionHost, stopStructuredAgentSessionRuntime } from './structured-agent-session-runtime' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' + +vi.mock('../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) let root: string @@ -107,7 +112,8 @@ describe('a process whose journal will not open', () => { earlier.pragma('user_version = 2') earlier.close() const before = await digest(path) - const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) + const reports = vi.mocked(traceAgentSessionError) + reports.mockClear() for (let attempt = 0; attempt < 3; attempt += 1) { await expect(install()).rejects.toMatchObject({ @@ -118,8 +124,8 @@ describe('a process whose journal will not open', () => { reason: 'journalCorrupt', message: 'Unable to load this chat.' }) - expect(warn).toHaveBeenCalledOnce() - const logged = String(warn.mock.calls[0]?.[1]) + expect(reports).toHaveBeenCalledOnce() + const logged = String(reports.mock.calls[0]?.[0].error) expect(logged).toContain(path) expect(logged).toContain('unreleased development build') expect(logged).toContain('move the file aside') @@ -143,8 +149,6 @@ describe('a process whose journal will not open', () => { }) describe('logging a journal that will not open', () => { - const OPEN_FAILED = '[structured-agent-session] opening the chat journal database failed' - async function writeJunkJournal(): Promise { const path = journalDatabasePath(root) await rm(`${path}-wal`, { force: true }) @@ -154,8 +158,11 @@ describe('logging a journal that will not open', () => { // Every chat request retries the open; the same failure each time is one log, not one per request. it('logs a repeated failure once, with its stack, and again after an open succeeds', async () => { - const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined) - const openFailureLogs = () => warn.mock.calls.filter(([message]) => message === OPEN_FAILED) + vi.mocked(traceAgentSessionError).mockClear() + const openFailureLogs = () => + vi + .mocked(traceAgentSessionError) + .mock.calls.filter(([report]) => report.step === 'journal-database-open') await install() await stopStructuredAgentSessionRuntime() await writeJunkJournal() @@ -166,8 +173,8 @@ describe('logging a journal that will not open', () => { }) } expect(openFailureLogs()).toHaveLength(1) - expect(openFailureLogs()[0]?.[1]).toBeInstanceOf(Error) - expect(openFailureLogs()[0]?.[1]).toHaveProperty('stack', expect.stringContaining('\n')) + expect(openFailureLogs()[0]?.[0].error).toBeInstanceOf(Error) + expect(openFailureLogs()[0]?.[0].error).toHaveProperty('stack', expect.stringContaining('\n')) await unlink(journalDatabasePath(root)) await install() diff --git a/src/main/runtime/structured-agent-session-journal-open.ts b/src/main/runtime/structured-agent-session-journal-open.ts index 6972a18a7960..3dbedb46f30b 100644 --- a/src/main/runtime/structured-agent-session-journal-open.ts +++ b/src/main/runtime/structured-agent-session-journal-open.ts @@ -3,6 +3,7 @@ import { JournalHostDatabase } from '../native-chat/agent-session-journal/journal-host-database' import { journalOpenRefusalError } from '../native-chat/agent-session-journal/journal-open-failure' import { recordStructuredAgentSessionHostInstallRefusal } from './structured-agent-session-host-refusal' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' // Every chat request retries a failed open, so each distinct failure is logged once, with its stack. let lastLoggedOpenFailure: string | null = null @@ -16,7 +17,7 @@ function logOpenFailureOnce(error: unknown): void { return } lastLoggedOpenFailure = failure - console.warn('[structured-agent-session] opening the chat journal database failed', error) + traceAgentSessionError({ step: 'journal-database-open', error }) } /** The journal database. A refusal is recorded for the gate and thrown to the caller; the next diff --git a/src/main/runtime/structured-agent-session-lifecycle-delivery.test.ts b/src/main/runtime/structured-agent-session-lifecycle-delivery.test.ts new file mode 100644 index 000000000000..ac0e822d7ed9 --- /dev/null +++ b/src/main/runtime/structured-agent-session-lifecycle-delivery.test.ts @@ -0,0 +1,67 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' +import { createStructuredAgentSessionLifecycleDelivery } from './structured-agent-session-lifecycle-delivery' + +vi.mock('../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) + +const EXIT = { + type: 'ended', + sessionId: 'session-1', + reason: 'provider crashed', + cause: 'unexpected-exit', + fence: 1, + acquisitionGeneration: 'generation-1' +} as const + +afterEach(() => { + vi.mocked(traceAgentSessionError).mockClear() +}) + +describe('structured agent-session lifecycle delivery', () => { + // No installer supplies a sink any more, so a failed exit recovery must still reach the trace. + it('reports a failed recovery with its session and keeps the chain moving', async () => { + const failure = new Error('journal write failed') + const handle = vi.fn().mockRejectedValueOnce(failure).mockResolvedValue(undefined) + const delivery = createStructuredAgentSessionLifecycleDelivery({ + handle, + drainObservedExits: async () => undefined + }) + + delivery.deliver(EXIT) + delivery.deliver({ ...EXIT, sessionId: 'session-2' }) + await delivery.drain() + + expect(handle).toHaveBeenCalledTimes(2) + expect(traceAgentSessionError).toHaveBeenCalledExactlyOnceWith({ + step: 'provider-exit-settlement', + sessionId: 'session-1', + error: failure + }) + }) + + it('reports a failed start settlement under its own step', async () => { + const failure = new Error('options write failed') + const delivery = createStructuredAgentSessionLifecycleDelivery({ + handle: vi.fn().mockRejectedValue(failure), + drainObservedExits: async () => undefined + }) + + delivery.deliver({ + type: 'started', + sessionId: 'session-1', + fence: 1, + acquisitionGeneration: 'generation-1', + reportedOptions: { model: 'model-1' }, + restoreSkippedOptions: [] + }) + await delivery.drain() + + expect(traceAgentSessionError).toHaveBeenCalledExactlyOnceWith({ + step: 'provider-started-settlement', + sessionId: 'session-1', + error: failure + }) + }) +}) diff --git a/src/main/runtime/structured-agent-session-lifecycle-delivery.ts b/src/main/runtime/structured-agent-session-lifecycle-delivery.ts index 961c4d50aa84..3ed90fccad25 100644 --- a/src/main/runtime/structured-agent-session-lifecycle-delivery.ts +++ b/src/main/runtime/structured-agent-session-lifecycle-delivery.ts @@ -7,10 +7,10 @@ // serialized step, and is tracked here so the same drain still waits for it. import type { StructuredAgentSessionLifecycleEvent } from '../native-chat/agent-session-wire/structured-agent-session-adapter' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' export function createStructuredAgentSessionLifecycleDelivery(input: { handle: (event: StructuredAgentSessionLifecycleEvent) => Promise | undefined - onError?: (input: { scope: string; error: unknown }) => void /** Exits the adapter has observed but not yet published. */ drainObservedExits: () => Promise }): { @@ -24,8 +24,11 @@ export function createStructuredAgentSessionLifecycleDelivery(input: { try { await input.handle(event) } catch (error) { - const scope = event.type === 'started' ? 'started' : 'exit' - input.onError?.({ scope: `structured-agent-session-${scope}:${event.sessionId}`, error }) + traceAgentSessionError({ + step: event.type === 'started' ? 'provider-started-settlement' : 'provider-exit-settlement', + sessionId: event.sessionId, + error + }) } } return { diff --git a/src/main/runtime/structured-agent-session-runtime.ts b/src/main/runtime/structured-agent-session-runtime.ts index 82c9803e2a76..4285b8bc03ab 100644 --- a/src/main/runtime/structured-agent-session-runtime.ts +++ b/src/main/runtime/structured-agent-session-runtime.ts @@ -55,6 +55,7 @@ import { createStructuredAgentEnvironmentResolvers } from './structured-agent-sh import type { ClaudeStructuredAuthPolicy } from '../claude-accounts/claude-structured-auth-policy' import { createStructuredClaudeRuntimeAdapter } from './structured-claude-runtime-adapter' import { createStructuredAgentSessionLifecycleDelivery } from './structured-agent-session-lifecycle-delivery' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' import { agentModelCatalogStore } from '../native-chat/agent-model-catalog/agent-model-catalog-store' import { modelCatalogHostDeps, @@ -101,7 +102,6 @@ export type StructuredAgentSessionRuntimeDeps = { /** Which login-shell variables Codex and Claude children inherit; absent inherits all. */ resolveShellEnvironmentPolicy?: () => NativeChatShellEnvironmentPolicy resolveCodexOverrides?: () => NodeJS.ProcessEnv - onError?: (input: { scope: string; error: unknown }) => void /** Every structured-session status projection, for host-side reactions such as the first-work * workspace rename that CLI agents get from their hooks. */ onSessionStatusChanged?: StructuredAgentSessionHostDeps['onSessionStatusChanged'] @@ -217,7 +217,6 @@ async function installOnJournal( let host: StructuredAgentSessionHost | null = null const lifecycle = createStructuredAgentSessionLifecycleDelivery({ handle: (event) => host?.handleAdapterEvent(event), - ...(deps.onError ? { onError: deps.onError } : {}), // Claude publishes an observed exit only after its close ladder and transcript write; Codex // publishes inside its own exit callback and needs nothing. drainObservedExits: () => claude.drainObservedExits() @@ -225,9 +224,10 @@ async function installOnJournal( const onDispatchSettledLate = ( settlement: Parameters[0] ): void => { - void host?.settleLateDispatch(settlement).catch((error) => - deps.onError?.({ - scope: `structured-agent-session-late-settlement:${settlement.sessionId}`, + void host?.settleLateDispatch(settlement).catch((error: unknown) => + traceAgentSessionError({ + step: 'late-dispatch-settlement', + sessionId: settlement.sessionId, error }) ) @@ -239,11 +239,8 @@ async function installOnJournal( sessionId, reason: DISPATCH_DOUBT_PROVIDER_IDLE }) - .catch((error) => - deps.onError?.({ - scope: `structured-agent-session-unanswered-dispatch:${sessionId}`, - error - }) + .catch((error: unknown) => + traceAgentSessionError({ step: 'unanswered-dispatch-release', sessionId, error }) ) } const codex = new CodexStructuredSessionAdapter({ @@ -315,8 +312,6 @@ async function installOnJournal( await deps.resolveLaunchArgs!(provider) } : {}), - onEventSinkError: ({ sessionId, error }) => - deps.onError?.({ scope: `structured-agent-session-journal:${sessionId}`, error }), ...(deps.onSessionStatusChanged ? { onSessionStatusChanged: deps.onSessionStatusChanged } : {}), ...(deps.statusSink ? { statusSink: deps.statusSink } : {}), ...(deps.hasOpenDispatch ? { hasOpenDispatch: deps.hasOpenDispatch } : {}), diff --git a/src/main/runtime/structured-agent-session-tab-retirement.ts b/src/main/runtime/structured-agent-session-tab-retirement.ts index aee5ef6d719d..2f6c71621e16 100644 --- a/src/main/runtime/structured-agent-session-tab-retirement.ts +++ b/src/main/runtime/structured-agent-session-tab-retirement.ts @@ -11,6 +11,7 @@ import type { RuntimeMobileSessionTabsSnapshot } from '../../shared/runtime-types' import { structuredAgentSessionTabId } from '../../shared/structured-agent-session-projection' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' /** The snapshot's tab for a structured session, matched by session id and by published tab id. */ export function findStructuredAgentSessionTab( @@ -74,6 +75,6 @@ export function retireSettledStructuredWorkerTab( try { runtime?.retireStructuredAgentSessionTabFromSnapshot?.(sessionId) } catch (error) { - console.warn('[orchestration] structured worker tab retirement failed', sessionId, error) + traceAgentSessionError({ step: 'worker-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 137b7ff6961f..ca1df51ec9fe 100644 --- a/src/main/runtime/structured-claude-pending-rewind.test.ts +++ b/src/main/runtime/structured-claude-pending-rewind.test.ts @@ -24,6 +24,11 @@ import type { AgentSessionRecordStore } from './agent-session-record-store' import { openTestAgentSessionRecordStore } from './agent-session-record-store-test-harness' import { createStructuredClaudeRuntimeAdapter } from './structured-claude-runtime-adapter' import { openTestJournalHostDatabase } from '../native-chat/agent-session-journal/journal-host-database-test-support' +import { traceAgentSessionError } from '../observability/agent-session-error-trace' + +vi.mock('../observability/agent-session-error-trace', () => ({ + traceAgentSessionError: vi.fn() +})) const caller = { callerKey: 'desktop' } const PROVIDER_SESSION_ID = claudeSessionIdForOrcaSession(HOST_TEST_SESSION) @@ -173,7 +178,7 @@ describe('Claude rewind is unsupported', () => { ) it('still attaches when settling the pending rewind fails, and logs it', async () => { - const warn = vi.spyOn(console, 'warn').mockImplementation(() => {}) + vi.mocked(traceAgentSessionError).mockClear() await seedPendingRewind('prepared') const transition = store.transitionHandoff.bind(store) vi.spyOn(store, 'transitionHandoff').mockImplementation((sessionId, apply) => @@ -189,9 +194,12 @@ describe('Claude rewind is unsupported', () => { await reattach() expect(store.getRecord(HOST_TEST_SESSION)?.rewind?.phase).toBe('prepared') - expect(warn).toHaveBeenCalledWith( - '[structured-rewind] pending Claude rewind was not settled:', - expect.objectContaining({ sessionId: HOST_TEST_SESSION, error: expect.any(Error) }) + expect(traceAgentSessionError).toHaveBeenCalledWith( + expect.objectContaining({ + step: 'rewind-recovery', + sessionId: HOST_TEST_SESSION, + error: expect.any(Error) + }) ) }) }) diff --git a/tests/e2e/codex-child-approval-activity-row.unit.test.ts b/tests/e2e/codex-child-approval-activity-row.unit.test.ts index dbb2a5d8e9cb..985982ab91e8 100644 --- a/tests/e2e/codex-child-approval-activity-row.unit.test.ts +++ b/tests/e2e/codex-child-approval-activity-row.unit.test.ts @@ -152,7 +152,7 @@ async function openHost() { }) const events: AgentSessionStatusEvent[] = [] feed.subscribe({ id: 'renderer', emit: (event) => events.push(event) }) - const deferred = createDeferredStructuredAgentSessionEventSink() + const deferred = createDeferredStructuredAgentSessionEventSink({ onFailure: () => {} }) const publish = (): void => feed.publish(SESSION, journal) deferred.bind({ journal, fence: 1, publish }) const prompts: string[] = []