From 0e79a84f822d71c8fd513b35aa5ab70ebcc9c670 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Tue, 20 Oct 2026 13:40:18 +0200 Subject: [PATCH 1/4] chore(diagnostics): trace Apple prepare subprocess lifecycle --- .github/actions/smoke-ios-run/action.yml | 2 + .../src/sessions/handlers/session-prepare.ts | 42 ++-- .../host-kit/src/internal/exec-trace.test.ts | 188 ++++++++++++++++++ packages/host-kit/src/internal/exec-trace.ts | 61 ++++++ packages/host-kit/src/internal/exec.test.ts | 161 --------------- packages/host-kit/src/internal/exec.ts | 152 +++++--------- .../src/lifecycle-prepare-diagnostics.test.ts | 53 +++++ packages/platform-apple/src/lifecycle.ts | 30 ++- .../platform-apple/src/simulator-state.ts | 33 ++- 9 files changed, 433 insertions(+), 289 deletions(-) create mode 100644 packages/host-kit/src/internal/exec-trace.test.ts create mode 100644 packages/host-kit/src/internal/exec-trace.ts create mode 100644 packages/platform-apple/src/lifecycle-prepare-diagnostics.test.ts diff --git a/.github/actions/smoke-ios-run/action.yml b/.github/actions/smoke-ios-run/action.yml index 768bce5cb0..da08a958c2 100644 --- a/.github/actions/smoke-ios-run/action.yml +++ b/.github/actions/smoke-ios-run/action.yml @@ -80,6 +80,8 @@ runs: XCTEST_LANE=pr node --experimental-strip-types scripts/xctest-run-summary.ts shell: bash - name: Preflight iOS runner through public CLI + env: + AGENT_DEVICE_EXEC_TRACE: '1' run: | pnpm clean:daemon # The public-SDK record is the cold-startup evidence; the CLI timer only wraps attach. diff --git a/packages/daemon/src/sessions/handlers/session-prepare.ts b/packages/daemon/src/sessions/handlers/session-prepare.ts index 79ad470941..7b3129d8fa 100644 --- a/packages/daemon/src/sessions/handlers/session-prepare.ts +++ b/packages/daemon/src/sessions/handlers/session-prepare.ts @@ -1,3 +1,4 @@ +import { emitDiagnostic } from '@agent-device/host-kit/diagnostics'; import type { DaemonResponse } from '@agent-device/kernel/contracts'; import type { DaemonPlatformServices } from '../../core/platform-services.ts'; import { prepareAppleRunnerRuntimeUse } from '@agent-device/contracts/application-lifecycle-runtime-plan'; @@ -61,18 +62,22 @@ export async function handlePrepareCommand(params: { // Device selection is side-effect free enough for facts admission. The bound lifecycle owns // readiness, keeping provider-first facts as the sole support authority. - const device = await resolveCommandDevice({ - session, - flags, - env: sessionStore.host.env, - platformServices: params.platformServices, - }); - const admission = await admitPrepareRuntime({ - device, - inspectFacts: params.inspectFacts, - platformServices: params.platformServices, - bindDevice: params.bindDevice, - }); + const device = await withPreparePhase('prepare_resolve_device', () => + resolveCommandDevice({ + session, + flags, + env: sessionStore.host.env, + platformServices: params.platformServices, + }), + ); + const admission = await withPreparePhase('prepare_admit_runtime', () => + admitPrepareRuntime({ + device, + inspectFacts: params.inspectFacts, + platformServices: params.platformServices, + bindDevice: params.bindDevice, + }), + ); if (admission.type === 'response') return admission.response; const startedAtMs = Date.now(); @@ -151,3 +156,16 @@ function normalizeOptionalTimingMs(value: number | undefined): number | undefine function normalizeTimingMs(value: number): number { return Number.isFinite(value) ? Math.max(0, Math.round(value)) : 0; } + +async function withPreparePhase( + phase: 'prepare_resolve_device' | 'prepare_admit_runtime', + run: () => Promise, +): Promise { + const started = performance.now(); + emitDiagnostic({ phase, data: { event: 'start' } }); + try { + return await run(); + } finally { + emitDiagnostic({ phase, durationMs: performance.now() - started, data: { event: 'settled' } }); + } +} diff --git a/packages/host-kit/src/internal/exec-trace.test.ts b/packages/host-kit/src/internal/exec-trace.test.ts new file mode 100644 index 0000000000..6c68cd1d24 --- /dev/null +++ b/packages/host-kit/src/internal/exec-trace.test.ts @@ -0,0 +1,188 @@ +import { ChildProcess, spawn } from 'node:child_process'; +import fs from 'node:fs'; +import path from 'node:path'; +import { PassThrough } from 'node:stream'; +import { afterEach, expect, test, vi } from 'vitest'; +import { runCmd, runCmdBackground, withCommandHost } from './exec.ts'; +import { flushDiagnosticsToSessionFile, withDiagnosticsScope } from './diagnostics.ts'; +import { mkdtempForTestSync } from './tmp-dir.fixtures.ts'; + +vi.mock('node:child_process', async (importOriginal) => ({ + ...(await importOriginal()), + spawn: vi.fn(), +})); +afterEach(() => vi.useRealTimers()); + +type Row = { + requestId: string; + durationMs: number; + data: { + execId: string; + event: string; + pid?: number; + timeoutMs?: number; + exitCode?: number; + signal?: string; + reason?: string; + }; +}; + +function processFixture() { + const child = Object.assign(new ChildProcess(), { + pid: 12345, + stdin: new PassThrough(), + stdout: new PassThrough(), + stderr: new PassThrough(), + }); + const kill = vi.spyOn(child, 'kill').mockReturnValue(true); + vi.mocked(spawn).mockReturnValue(child); + return { + child, + kill, + exit(code: number) { + Object.defineProperty(child, 'exitCode', { value: code, configurable: true }); + child.emit('exit', code, null); + }, + }; +} + +async function capture(debug: boolean, run: () => Promise, envTrace = false) { + const logPath = path.join(mkdtempForTestSync('exec-timeline-'), 'request.ndjson'); + await withCommandHost( + { + host: { + env: { AGENT_DEVICE_EXEC_TRACE: envTrace ? '1' : undefined }, + cwd: process.cwd(), + }, + requestEnv: undefined, + }, + () => + withDiagnosticsScope({ requestId: 'prepare-request', debug, logPath }, async () => { + await run(); + flushDiagnosticsToSessionFile(); + }), + ); + return fs.existsSync(logPath) + ? fs + .readFileSync(logPath, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line) as Row) + : []; +} + +for (const debug of [false, true]) { + test(`exit before deadline with inherited stdio keeps timeout semantics (trace=${debug})`, async () => { + vi.useFakeTimers(); + const fixture = processFixture(); + const rows = await capture(debug, async () => { + const result = runCmd('xcrun', ['simctl', '--set', '/private/set', 'list', 'devices', '-j'], { + timeoutMs: 100, + }); + const rejection = expect(result).rejects.toMatchObject({ + code: 'COMMAND_FAILED', + details: { timeoutMs: 100, exitCode: 0 }, + }); + fixture.child.emit('spawn'); + fixture.exit(0); + await vi.advanceTimersByTimeAsync(100); + await rejection; + fixture.child.emit('close', 0, null); + }); + expect(fixture.kill).toHaveBeenCalledTimes(0); + if (!debug) { + expect(rows).toEqual([]); + return; + } + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + 'exit', + 'deadline', + 'settled', + 'close', + ]); + expect(rows.find((row) => row.data.event === 'settled')?.data.reason).toBe('timeout'); + expect(rows.find((row) => row.data.event === 'exit')?.data.exitCode).toBe(0); + expect(rows.every((row) => row.requestId === 'prepare-request')).toBe(true); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); + expect(rows.slice(1).every((row) => row.data.pid === 12345 && row.data.timeoutMs === 100)).toBe( + true, + ); + expect(rows.map((row) => row.durationMs)).toEqual( + rows.map((row) => row.durationMs).sort((a, b) => a - b), + ); + }); +} + +test('deadline before exit records the signal and one settlement without waiting for close', async () => { + vi.useFakeTimers(); + const fixture = processFixture(); + const rows = await capture(true, async () => { + const result = runCmd('xcrun', ['simctl', 'list', 'devices', '-j'], { timeoutMs: 100 }); + const rejection = expect(result).rejects.toMatchObject({ code: 'COMMAND_FAILED' }); + fixture.child.emit('spawn'); + await vi.advanceTimersByTimeAsync(100); + Object.defineProperty(fixture.child, 'signalCode', { value: 'SIGKILL' }); + fixture.child.emit('exit', null, 'SIGKILL'); + await rejection; + fixture.child.emit('close', null, 'SIGKILL'); + }); + expect(fixture.kill).toHaveBeenCalledExactlyOnceWith('SIGKILL'); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + 'deadline', + 'exit', + 'settled', + 'close', + ]); + expect(rows.find((row) => row.data.event === 'exit')?.data.signal).toBe('SIGKILL'); +}); + +test('successful close preserves output and tracing retains safe metadata without process inputs', async () => { + const fixture = processFixture(); + const secret = 'unregistered-secret-value'; + const rows = await capture( + false, + async () => { + const result = runCmd('/usr/bin/tool', ['--token', secret], { + env: { SECRET: secret }, + stdin: secret, + }); + fixture.child.emit('spawn'); + fixture.child.stdout.write('ok'); + fixture.exit(0); + fixture.child.emit('close', 0, null); + expect(await result).toMatchObject({ stdout: 'ok', stderr: '', exitCode: 0 }); + }, + true, + ); + expect(JSON.stringify(rows)).not.toContain(secret); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + 'exit', + 'close', + 'settled', + ]); + expect(rows.at(-1)?.data.reason).toBe('success'); + expect(JSON.stringify(rows)).not.toContain('args'); +}); + +test('background tracing is opt-in and retains a successful completion', async () => { + const fixture = processFixture(); + const rows = await capture( + false, + async () => { + const { wait } = runCmdBackground('/usr/bin/tool', ['private-argument']); + fixture.child.emit('spawn'); + fixture.exit(0); + fixture.child.emit('close', 0, null); + expect((await wait).exitCode).toBe(0); + }, + true, + ); + expect(rows.map((row) => row.data.event)).toEqual(['spawn_start', 'spawn', 'settled']); + expect(JSON.stringify(rows)).not.toContain('private-argument'); +}); diff --git a/packages/host-kit/src/internal/exec-trace.ts b/packages/host-kit/src/internal/exec-trace.ts new file mode 100644 index 0000000000..70bed6fbd2 --- /dev/null +++ b/packages/host-kit/src/internal/exec-trace.ts @@ -0,0 +1,61 @@ +import { randomUUID } from 'node:crypto'; +import path from 'node:path'; +import { emitDiagnostic, getDiagnosticsMeta, updateDiagnosticsScope } from './diagnostics.ts'; + +export type ExecSettlementReason = + | 'success' + | 'exit_failure' + | 'timeout' + | 'abort' + | 'spawn_error' + | 'stdin_error'; + +type ExecLifecycleEvent = + | 'spawn_start' + | 'spawn' + | 'deadline' + | 'abort' + | 'error' + | 'exit' + | 'close' + | 'settled'; +type ExecLifecycleData = { + pid?: number; + exitCode?: number | null; + signal?: NodeJS.Signals | null; + reason?: ExecSettlementReason; +}; + +export function createExecTraceContext( + cmd: string, + args: readonly string[], + timeoutMs: number | undefined, + envTraceEnabled: boolean, +): { emit(event: ExecLifecycleEvent, data?: ExecLifecycleData): void } { + const meta = getDiagnosticsMeta(); + if (!meta.debug && !envTraceEnabled) return { emit: () => {} }; + if (envTraceEnabled && !meta.flushOnSuccess) updateDiagnosticsScope({ flushOnSuccess: true }); + const started = performance.now(); + const execId = randomUUID(); + let pid: number | undefined; + const command = path.basename(cmd); + const simctlArgs = args[1] === '--set' ? args.slice(3) : args.slice(1); + const operation = + command === 'xcrun' && + args[0] === 'simctl' && + simctlArgs.length === 3 && + simctlArgs.join(' ') === 'list devices -j' + ? 'simctl_list_devices' + : undefined; + const emit = (event: ExecLifecycleEvent, data: ExecLifecycleData = {}): void => { + pid = data.pid ?? pid; + emitDiagnostic({ + level: 'debug', + phase: 'exec_command', + durationMs: performance.now() - started, + data: { execId, command, operation, event, pid, timeoutMs, ...data }, + }); + }; + emit('spawn_start'); + return { emit }; +} diff --git a/packages/host-kit/src/internal/exec.test.ts b/packages/host-kit/src/internal/exec.test.ts index dee9c69a41..fedc7daaee 100644 --- a/packages/host-kit/src/internal/exec.test.ts +++ b/packages/host-kit/src/internal/exec.test.ts @@ -2,7 +2,6 @@ import { test } from 'vitest'; import assert from 'node:assert/strict'; import fs from 'node:fs'; import path from 'node:path'; -import { flushDiagnosticsToSessionFile, withDiagnosticsScope } from './diagnostics.ts'; import { coerceExecResult, commandDeveloperDir, @@ -62,31 +61,6 @@ test('runCmd abort keeps cancellation details while writing stdin', async () => await assertRejectsRequestCanceled(promise); }); -test('runCmd emits exec_command diagnostics when the scope is debug-enabled', async () => { - const logPath = path.join(mkdtempForTestSync('agent-device-exec-debug-'), 'diag.ndjson'); - const diagnosticsPath = await withDiagnosticsScope( - { - session: 'exec-debug', - requestId: 'exec-debug-1', - command: 'debug', - debug: true, - logPath, - }, - async () => { - await runCmd(process.execPath, ['-e', 'process.stdout.write("ok")']); - return flushDiagnosticsToSessionFile()?.path ?? null; - }, - ); - - const execEvent = readExecDiagnosticEvent(diagnosticsPath); - assert.equal(execEvent?.level, 'debug'); - assert.equal(execEvent?.phase, 'exec_command'); - assert.equal(execEvent?.data?.command, process.execPath); - assert.deepEqual(execEvent?.data?.argsPrefix, ['-e', 'process.stdout.write("ok")']); - assert.equal(execEvent?.data?.omittedArgCount, undefined); - assert.equal(typeof execEvent?.durationMs, 'number'); -}); - test('runCmd writes stdin through pipeline', async () => { const stdin = Buffer.alloc(256_000, 'a'); const result = await runCmd( @@ -105,39 +79,6 @@ test('runCmd writes stdin through pipeline', async () => { assert.equal(result.stdout, String(stdin.length)); }); -test( - 'runCmdBackground emits bounded exec_command diagnostics when AGENT_DEVICE_EXEC_TRACE is enabled', - { concurrent: false }, - async () => { - const diagnosticsPath = await withExecTraceEnv( - async () => - await withDiagnosticsScope( - { - session: 'exec-trace', - requestId: 'exec-trace-1', - command: 'background', - }, - async () => { - const { wait } = runCmdBackground(process.execPath, [ - '-e', - 'process.stdout.write("ok")', - 'a', - 'b', - 'c', - 'd', - 'e', - 'f', - ]); - await wait; - return flushDiagnosticsToSessionFile()?.path ?? null; - }, - ), - ); - - assertBackgroundExecTraceEvents(readExecDiagnosticEvents(diagnosticsPath)); - }, -); - test('runCmdBackground can leave output streams to the caller', async () => { const { child, wait } = runCmdBackground( process.execPath, @@ -163,26 +104,6 @@ test('runCmdBackground can leave output streams to the caller', async () => { assert.equal(stderr, 'err'); }); -test('runCmd stays silent when exec tracing is not enabled', async () => { - const diagnosticsPath = await withCommandHost( - { host: hostWith({ AGENT_DEVICE_EXEC_TRACE: undefined }), requestEnv: undefined }, - async () => - await withDiagnosticsScope( - { - session: 'exec-silent', - requestId: 'exec-silent-1', - command: 'home', - }, - async () => { - await runCmd(process.execPath, ['-e', 'process.stdout.write("ok")']); - return flushDiagnosticsToSessionFile()?.path ?? null; - }, - ), - ); - - assert.equal(diagnosticsPath, null); -}); - test('runCmdBackground aborts with request cancellation details', async () => { const controller = new AbortController(); const { wait } = runCmdBackground(process.execPath, ['-e', 'setTimeout(() => {}, 10_000)'], { @@ -295,88 +216,6 @@ test('whichCmd ignores directories that match a command name in PATH', async () } }); -function readExecDiagnosticEvents(diagnosticsPath: string | null): Array<{ - level?: string; - phase?: string; - durationMs?: number; - data?: Record; -}> { - if (!diagnosticsPath) return []; - const rows = fs - .readFileSync(diagnosticsPath, 'utf8') - .trim() - .split('\n') - .map( - (line) => - JSON.parse(line) as { - level?: string; - phase?: string; - durationMs?: number; - data?: Record; - }, - ); - return rows.filter((row) => row.phase === 'exec_command'); -} - -function readExecDiagnosticEvent(diagnosticsPath: string | null): { - level?: string; - phase?: string; - durationMs?: number; - data?: Record; -} | null { - return readExecDiagnosticEvents(diagnosticsPath)[0] ?? null; -} - -async function withExecTraceEnv(fn: () => Promise): Promise { - return await withCommandHost( - { host: hostWith({ AGENT_DEVICE_EXEC_TRACE: '1' }), requestEnv: undefined }, - fn, - ); -} - -function assertBackgroundExecTraceEvents( - execEvents: Array<{ - level?: string; - phase?: string; - durationMs?: number; - data?: Record; - }>, -): void { - assert.deepEqual(execEvents.map(summarizeExecEvent), [ - { - phase: 'exec_command', - command: process.execPath, - event: 'spawn', - durationType: 'undefined', - argsPrefix: ['-e', 'process.stdout.write("ok")', 'a', 'b', 'c', 'd'], - omittedArgCount: 2, - }, - { - phase: 'exec_command', - command: process.execPath, - event: 'exit', - durationType: 'number', - argsPrefix: ['-e', 'process.stdout.write("ok")', 'a', 'b', 'c', 'd'], - omittedArgCount: 2, - }, - ]); -} - -function summarizeExecEvent(event: { - phase?: string; - durationMs?: number; - data?: Record; -}): Record { - return { - phase: event.phase, - command: event.data?.command, - event: event.data?.event, - durationType: typeof event.durationMs, - argsPrefix: event.data?.argsPrefix, - omittedArgCount: event.data?.omittedArgCount, - }; -} - test('requireExecSuccess passes a zero-exit result through untouched', () => { const result: ExecResult = { stdout: 'ok', stderr: '', exitCode: 0 }; assert.equal( diff --git a/packages/host-kit/src/internal/exec.ts b/packages/host-kit/src/internal/exec.ts index 71785d2c98..1ad60f541b 100644 --- a/packages/host-kit/src/internal/exec.ts +++ b/packages/host-kit/src/internal/exec.ts @@ -6,7 +6,7 @@ import { spawn, spawnSync, type ChildProcess, type StdioOptions } from 'node:chi import { Readable } from 'node:stream'; import { pipeline } from 'node:stream/promises'; import { AppError, createRequestCanceledError } from '@agent-device/kernel/errors'; -import { emitDiagnostic, getDiagnosticsMeta, updateDiagnosticsScope } from './diagnostics.ts'; +import { createExecTraceContext, type ExecSettlementReason } from './exec-trace.ts'; import { parseBooleanLiteral, type EnvMap, @@ -88,7 +88,6 @@ export type ExecBackgroundOptions = Omit & { const BARE_COMMAND_RE = /^[A-Za-z0-9][A-Za-z0-9._+-]*$/; const WINDOWS_PATH_EXTENSIONS = ['.com', '.exe', '.bat', '.cmd']; -const EXEC_DIAGNOSTIC_ARG_LIMIT = 6; export type CommandExecutorOverride = ( cmd: string, args: readonly string[], @@ -208,7 +207,13 @@ function runSpawnedCommand( options: ExecStreamOptions = {}, ): Promise { const executable = normalizeExecutableCommand(cmd); - const execTrace = createExecTraceContext(); + const execTrace = createExecTraceContext( + cmd, + args, + normalizeTimeoutMs(options.timeoutMs), + parseBooleanLiteral(commandHostScope.getStore()?.host.env.AGENT_DEVICE_EXEC_TRACE ?? '') === + true, + ); return new Promise((resolve, reject) => { const child = spawn(executable, args, { cwd: options.cwd, @@ -218,6 +223,7 @@ function runSpawnedCommand( windowsHide: true, shell: false, }); + child.once('spawn', () => execTrace.emit('spawn', { pid: child.pid })); options.onSpawn?.(child); let stdout = ''; @@ -228,20 +234,27 @@ function runSpawnedCommand( const timeoutMs = normalizeTimeoutMs(options.timeoutMs); let timeoutHandle: NodeJS.Timeout | null = null; let settled = false; - function finish(): boolean { + function finish(reason: ExecSettlementReason): boolean { if (settled) return false; settled = true; if (timeoutHandle) clearTimeout(timeoutHandle); abort.dispose(); destroyCommandStreams(child); - execTrace.emitForegroundCompletion(cmd, args); + execTrace.emit('settled', { reason }); return true; } - function fail(error: AppError): void { - if (finish()) reject(error); + function fail(error: AppError, reason: ExecSettlementReason): void { + if (finish(reason)) reject(error); } function settle(code: number | null): void { - if (!finish()) return; + const finalReason = abort.didAbort + ? 'abort' + : didTimeout + ? 'timeout' + : (code ?? 1) !== 0 && !options.allowFailure + ? 'exit_failure' + : 'success'; + if (!finish(finalReason)) return; const finalExitCode = code ?? 1; if (!abort.didAbort && didTimeout && timeoutMs) { reject(createTimeoutError(executable, cmd, args, timeoutMs, finalExitCode, stdout, stderr)); @@ -275,9 +288,13 @@ function runSpawnedCommand( killProcessTree: () => killProcessTree(child, options), settle, }); - const abort = watchCommandAbort(options, settlement.requestKill); + const abort = watchCommandAbort(options, () => { + execTrace.emit('abort'); + settlement.requestKill(); + }); timeoutHandle = timeoutMs ? setTimeout(() => { + execTrace.emit('deadline'); didTimeout = true; settlement.requestKill(); }, timeoutMs) @@ -289,7 +306,7 @@ function runSpawnedCommand( void writeChildStdin(child, options.stdin).catch((error: unknown) => { if (abort.didAbort || didTimeout) return; if (isEpipeError(error)) return; - fail(createStdinError(executable, cmd, args, error)); + fail(createStdinError(executable, cmd, args, error), 'stdin_error'); killProcessTree(child, options); }); @@ -310,11 +327,18 @@ function runSpawnedCommand( }); child.on('error', (err) => { - fail(spawnRejectionError(abort, executable, cmd, args, err)); + execTrace.emit('error'); + fail(spawnRejectionError(abort, executable, cmd, args, err), 'spawn_error'); }); - child.once('exit', settlement.recordExit); - child.once('close', settle); + child.once('exit', (code, signal) => { + execTrace.emit('exit', { exitCode: code, signal }); + settlement.recordExit(code); + }); + child.once('close', (code, signal) => { + execTrace.emit('close', { exitCode: code, signal }); + settle(code); + }); }); } @@ -479,7 +503,13 @@ export function runCmdBackground( options: ExecBackgroundOptions = {}, ): ExecBackgroundResult { const executable = normalizeExecutableCommand(cmd); - const execTrace = createExecTraceContext(); + const execTrace = createExecTraceContext( + cmd, + args, + undefined, + parseBooleanLiteral(commandHostScope.getStore()?.host.env.AGENT_DEVICE_EXEC_TRACE ?? '') === + true, + ); const child = spawn(executable, args, { cwd: options.cwd, env: resolveSpawnEnv(options.env), @@ -488,7 +518,7 @@ export function runCmdBackground( windowsHide: true, shell: false, }); - execTrace.emitBackgroundSpawn(cmd, args); + child.once('spawn', () => execTrace.emit('spawn', { pid: child.pid })); let stdout = ''; let stderr = ''; @@ -513,7 +543,16 @@ export function runCmdBackground( settled = true; abort.dispose(); destroyCommandStreams(child); - execTrace.emitBackgroundCompletion(cmd, args, event); + execTrace.emit('settled', { + reason: + event === 'error' + ? 'spawn_error' + : abort.didAbort + ? 'abort' + : (child.exitCode ?? 1) !== 0 && !options.allowFailure + ? 'exit_failure' + : 'success', + }); return true; } function settle(code: number | null): void { @@ -550,87 +589,6 @@ export function runCmdBackground( return { child, wait }; } -type ExecTraceContext = { - emitBackgroundCompletion: (cmd: string, args: readonly string[], event: 'error' | 'exit') => void; - emitBackgroundSpawn: (cmd: string, args: readonly string[]) => void; - emitForegroundCompletion: (cmd: string, args: readonly string[]) => void; -}; - -function createExecTraceContext(): ExecTraceContext { - const diagnosticsMeta = getDiagnosticsMeta(); - const diagnosticsDebugEnabled = diagnosticsMeta.debug === true; - const envTraceEnabled = - parseBooleanLiteral(commandHostScope.getStore()?.host.env.AGENT_DEVICE_EXEC_TRACE ?? '') === - true; - if (!diagnosticsDebugEnabled && !envTraceEnabled) { - return createDisabledExecTraceContext(); - } - if (envTraceEnabled && diagnosticsMeta.flushOnSuccess !== true) { - updateDiagnosticsScope({ flushOnSuccess: true }); - } - const startedAtMs = Date.now(); - let completionEmitted = false; - return { - emitForegroundCompletion: (cmd, args) => { - if (completionEmitted) return; - completionEmitted = true; - emitExecCommandDiagnostic({ - cmd, - args, - startedAtMs, - }); - }, - emitBackgroundSpawn: (cmd, args) => { - emitExecCommandDiagnostic({ - cmd, - args, - data: { event: 'spawn' }, - }); - }, - emitBackgroundCompletion: (cmd, args, event) => { - if (completionEmitted) return; - completionEmitted = true; - emitExecCommandDiagnostic({ - cmd, - args, - startedAtMs, - data: { event }, - }); - }, - }; -} - -function createDisabledExecTraceContext(): ExecTraceContext { - return { - emitForegroundCompletion: () => {}, - emitBackgroundSpawn: () => {}, - emitBackgroundCompletion: () => {}, - }; -} - -function emitExecCommandDiagnostic(params: { - cmd: string; - args: readonly string[]; - startedAtMs?: number; - data?: Record; -}): void { - const argsPrefix = params.args.slice(0, EXEC_DIAGNOSTIC_ARG_LIMIT); - emitDiagnostic({ - level: 'debug', - phase: 'exec_command', - durationMs: - params.startedAtMs === undefined ? undefined : Math.max(0, Date.now() - params.startedAtMs), - data: { - command: params.cmd, - argsPrefix, - ...(params.args.length > argsPrefix.length - ? { omittedArgCount: params.args.length - argsPrefix.length } - : {}), - ...(params.data ?? {}), - }, - }); -} - function normalizeExecutableCommand(cmd: string): string { const candidate = normalizeExecutableLookup(cmd); if (!candidate) { diff --git a/packages/platform-apple/src/lifecycle-prepare-diagnostics.test.ts b/packages/platform-apple/src/lifecycle-prepare-diagnostics.test.ts new file mode 100644 index 0000000000..2d5d3c19a5 --- /dev/null +++ b/packages/platform-apple/src/lifecycle-prepare-diagnostics.test.ts @@ -0,0 +1,53 @@ +import fs from 'node:fs'; +import path from 'node:path'; +import { expect, test, vi } from 'vitest'; +import { mkdtempForTestSync } from '@agent-device/test-kit'; +import { + flushDiagnosticsToSessionFile, + withDiagnosticsScope, +} from '@agent-device/host-kit/diagnostics'; +import { AppError } from '@agent-device/kernel/errors'; +import { bindAppleApplicationLifecycle } from './lifecycle.ts'; +import { coldSimulatorLifecycleHost, simulator } from './lifecycle.fixtures.ts'; + +for (const failed of [false, true]) { + test(`prepare retains readiness and inventory phase boundaries on ${failed ? 'failure' : 'success'}`, async () => { + const { host, prepareRunner } = coldSimulatorLifecycleHost(); + const failure = new AppError('COMMAND_FAILED', 'fixture timeout', { timeoutMs: 15_000 }); + if (failed) vi.mocked(host.appleTools.run).mockRejectedValueOnce(failure); + const logPath = path.join(mkdtempForTestSync('prepare-phases-'), 'request.ndjson'); + await withDiagnosticsScope( + { requestId: 'prepare', logPath, flushOnSuccess: true }, + async () => { + const operation = bindAppleApplicationLifecycle({ + host, + device: simulator, + signal: new AbortController().signal, + }).prepareAppleRunner({ timeoutMs: 100_000, execution: {} }); + if (failed) await expect(operation).rejects.toBe(failure); + else await operation; + flushDiagnosticsToSessionFile(); + }, + ); + const rows = fs + .readFileSync(logPath, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line)); + expect(rows.map((row) => [row.phase, row.data.event])).toEqual([ + ['prepare_apple_runner', 'readiness_start'], + ['simulator_state', 'start'], + ['simulator_state', 'settled'], + ...(!failed ? [['prepare_apple_runner', 'runner_start']] : []), + ['prepare_apple_runner', 'settled'], + ]); + expect( + rows + .filter((row) => row.phase === 'simulator_state') + .every((row) => row.data.timeoutMs === 15_000), + ).toBe(true); + expect(prepareRunner).toHaveBeenCalledTimes(failed ? 0 : 1); + expect(rows.at(-1).durationMs).toBeGreaterThanOrEqual(0); + expect(rows[0].data.remainingMs).toBeGreaterThan(0); + }); +} diff --git a/packages/platform-apple/src/lifecycle.ts b/packages/platform-apple/src/lifecycle.ts index 79c4fb7177..f530586e2a 100644 --- a/packages/platform-apple/src/lifecycle.ts +++ b/packages/platform-apple/src/lifecycle.ts @@ -1,3 +1,4 @@ +import { emitDiagnostic } from '@agent-device/host-kit/diagnostics'; import { type ApplicationLifecycleRuntimeOperations, type AppleRunnerSessionPrewarmOptions, @@ -458,14 +459,27 @@ async function prepareAppleRunner( // One budget covers the boot and the runner: a cold Simulator's boot spends part of it, and // the runner preparation gets what is left rather than the full budget again. const deadlineAtMs = Date.now() + input.timeoutMs; - const readied = await ensureAppleReady(host, device, signal, { deadlineAtMs }); - const timeoutMs = Math.max(1, deadlineAtMs - Date.now()); - const prepared = await host.appleApplications.prepareRunner( - readied, - { ...input, timeoutMs }, - signal, - ); - return { readied, prepared }; + const traceStarted = performance.now(); + const trace = (event: 'readiness_start' | 'runner_start' | 'settled') => + emitDiagnostic({ + phase: 'prepare_apple_runner', + durationMs: performance.now() - traceStarted, + data: { event, timeoutMs: input.timeoutMs, remainingMs: deadlineAtMs - Date.now() }, + }); + trace('readiness_start'); + try { + const readied = await ensureAppleReady(host, device, signal, { deadlineAtMs }); + const timeoutMs = Math.max(1, deadlineAtMs - Date.now()); + trace('runner_start'); + const prepared = await host.appleApplications.prepareRunner( + readied, + { ...input, timeoutMs }, + signal, + ); + return { readied, prepared }; + } finally { + trace('settled'); + } } type RunnerPrewarm = Readonly<{ diff --git a/packages/platform-apple/src/simulator-state.ts b/packages/platform-apple/src/simulator-state.ts index df6235deaa..83ae2e6b2b 100644 --- a/packages/platform-apple/src/simulator-state.ts +++ b/packages/platform-apple/src/simulator-state.ts @@ -1,3 +1,4 @@ +import { emitDiagnostic } from '@agent-device/host-kit/diagnostics'; import type { DeviceInfo } from '@agent-device/kernel/device'; import type { AppleToolHost } from '@agent-device/contracts/platform-runtime-host'; import { readSimctlDeviceState, scopeSimctlArgsForDevice } from './core/simctl.ts'; @@ -8,15 +9,25 @@ export async function getSimulatorState( signal: AbortSignal, timeoutMs: number, ): Promise { - const result = await appleTools.run( - { - tool: 'simctl', - args: scopeSimctlArgsForDevice(device, ['list', 'devices', '-j']), - allowFailure: true, - timeoutMs, - }, - signal, - ); - if (result.exitCode !== 0) return null; - return readSimctlDeviceState(result.stdout, device.id); + const started = performance.now(); + emitDiagnostic({ phase: 'simulator_state', data: { event: 'start', timeoutMs } }); + try { + const result = await appleTools.run( + { + tool: 'simctl', + args: scopeSimctlArgsForDevice(device, ['list', 'devices', '-j']), + allowFailure: true, + timeoutMs, + }, + signal, + ); + if (result.exitCode !== 0) return null; + return readSimctlDeviceState(result.stdout, device.id); + } finally { + emitDiagnostic({ + phase: 'simulator_state', + durationMs: performance.now() - started, + data: { event: 'settled', timeoutMs }, + }); + } } From e62edc42dd4f3e3c7042c621dac80bfb2644b625 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Tue, 20 Oct 2026 13:47:47 +0200 Subject: [PATCH 2/4] fix(diagnostics): retain late subprocess close events --- .../host-kit/src/internal/exec-trace.test.ts | 34 +++++++++++++++++++ packages/host-kit/src/internal/exec-trace.ts | 10 +++++- 2 files changed, 43 insertions(+), 1 deletion(-) diff --git a/packages/host-kit/src/internal/exec-trace.test.ts b/packages/host-kit/src/internal/exec-trace.test.ts index 6c68cd1d24..7c24aab111 100644 --- a/packages/host-kit/src/internal/exec-trace.test.ts +++ b/packages/host-kit/src/internal/exec-trace.test.ts @@ -186,3 +186,37 @@ test('background tracing is opt-in and retains a successful completion', async ( expect(rows.map((row) => row.data.event)).toEqual(['spawn_start', 'spawn', 'settled']); expect(JSON.stringify(rows)).not.toContain('private-argument'); }); + +test('environment-only trace persists close after the request finalization flush', async () => { + vi.useFakeTimers(); + const fixture = processFixture(); + const logPath = path.join(mkdtempForTestSync('exec-late-close-'), 'request.ndjson'); + await withCommandHost( + { host: { env: { AGENT_DEVICE_EXEC_TRACE: '1' }, cwd: process.cwd() }, requestEnv: undefined }, + () => + withDiagnosticsScope({ requestId: 'late-close', logPath }, async () => { + const result = runCmd('xcrun', ['simctl', 'list', 'devices', '-j'], { timeoutMs: 100 }); + const rejection = expect(result).rejects.toMatchObject({ code: 'COMMAND_FAILED' }); + fixture.child.emit('spawn'); + fixture.exit(0); + await vi.advanceTimersByTimeAsync(100); + await rejection; + flushDiagnosticsToSessionFile(); + fixture.child.emit('close', 0, null); + const rows = fs + .readFileSync(logPath, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line) as Row); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + 'exit', + 'deadline', + 'settled', + 'close', + ]); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); + }), + ); +}); diff --git a/packages/host-kit/src/internal/exec-trace.ts b/packages/host-kit/src/internal/exec-trace.ts index 70bed6fbd2..769c58547a 100644 --- a/packages/host-kit/src/internal/exec-trace.ts +++ b/packages/host-kit/src/internal/exec-trace.ts @@ -1,6 +1,11 @@ import { randomUUID } from 'node:crypto'; import path from 'node:path'; -import { emitDiagnostic, getDiagnosticsMeta, updateDiagnosticsScope } from './diagnostics.ts'; +import { + emitDiagnostic, + flushDiagnosticsToSessionFile, + getDiagnosticsMeta, + updateDiagnosticsScope, +} from './diagnostics.ts'; export type ExecSettlementReason = | 'success' @@ -38,6 +43,7 @@ export function createExecTraceContext( const started = performance.now(); const execId = randomUUID(); let pid: number | undefined; + let settlementEmitted = false; const command = path.basename(cmd); const simctlArgs = args[1] === '--set' ? args.slice(3) : args.slice(1); const operation = @@ -55,6 +61,8 @@ export function createExecTraceContext( durationMs: performance.now() - started, data: { execId, command, operation, event, pid, timeoutMs, ...data }, }); + if (event === 'settled') settlementEmitted = true; + if (event === 'close' && settlementEmitted && envTraceEnabled) flushDiagnosticsToSessionFile(); }; emit('spawn_start'); return { emit }; From fb7d9e0b2d4aa2b0379662b25e1b8db8e8a38970 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Tue, 20 Oct 2026 16:42:51 +0200 Subject: [PATCH 3/4] refactor(diagnostics): consolidate phase timing and subprocess tracing --- .../src/sessions/handlers/session-prepare.ts | 51 +++--- .../host-kit/src/internal/diagnostics.test.ts | 42 +++++ packages/host-kit/src/internal/diagnostics.ts | 29 +-- .../host-kit/src/internal/exec-trace.test.ts | 167 ++++++++++++++---- packages/host-kit/src/internal/exec-trace.ts | 19 +- packages/host-kit/src/internal/exec.ts | 34 ++-- packages/platform-apple/src/lifecycle.ts | 46 ++--- .../platform-apple/src/simulator-state.ts | 41 ++--- 8 files changed, 286 insertions(+), 143 deletions(-) diff --git a/packages/daemon/src/sessions/handlers/session-prepare.ts b/packages/daemon/src/sessions/handlers/session-prepare.ts index 7b3129d8fa..fdcba60a7c 100644 --- a/packages/daemon/src/sessions/handlers/session-prepare.ts +++ b/packages/daemon/src/sessions/handlers/session-prepare.ts @@ -1,4 +1,4 @@ -import { emitDiagnostic } from '@agent-device/host-kit/diagnostics'; +import { withDiagnosticTimer } from '@agent-device/host-kit/diagnostics'; import type { DaemonResponse } from '@agent-device/kernel/contracts'; import type { DaemonPlatformServices } from '../../core/platform-services.ts'; import { prepareAppleRunnerRuntimeUse } from '@agent-device/contracts/application-lifecycle-runtime-plan'; @@ -62,21 +62,29 @@ export async function handlePrepareCommand(params: { // Device selection is side-effect free enough for facts admission. The bound lifecycle owns // readiness, keeping provider-first facts as the sole support authority. - const device = await withPreparePhase('prepare_resolve_device', () => - resolveCommandDevice({ - session, - flags, - env: sessionStore.host.env, - platformServices: params.platformServices, - }), + const device = await withDiagnosticTimer( + 'prepare_resolve_device', + () => + resolveCommandDevice({ + session, + flags, + env: sessionStore.host.env, + platformServices: params.platformServices, + }), + undefined, + 'start', ); - const admission = await withPreparePhase('prepare_admit_runtime', () => - admitPrepareRuntime({ - device, - inspectFacts: params.inspectFacts, - platformServices: params.platformServices, - bindDevice: params.bindDevice, - }), + const admission = await withDiagnosticTimer( + 'prepare_admit_runtime', + () => + admitPrepareRuntime({ + device, + inspectFacts: params.inspectFacts, + platformServices: params.platformServices, + bindDevice: params.bindDevice, + }), + undefined, + 'start', ); if (admission.type === 'response') return admission.response; @@ -156,16 +164,3 @@ function normalizeOptionalTimingMs(value: number | undefined): number | undefine function normalizeTimingMs(value: number): number { return Number.isFinite(value) ? Math.max(0, Math.round(value)) : 0; } - -async function withPreparePhase( - phase: 'prepare_resolve_device' | 'prepare_admit_runtime', - run: () => Promise, -): Promise { - const started = performance.now(); - emitDiagnostic({ phase, data: { event: 'start' } }); - try { - return await run(); - } finally { - emitDiagnostic({ phase, durationMs: performance.now() - started, data: { event: 'settled' } }); - } -} diff --git a/packages/host-kit/src/internal/diagnostics.test.ts b/packages/host-kit/src/internal/diagnostics.test.ts index 088c9e23db..237e26f19b 100644 --- a/packages/host-kit/src/internal/diagnostics.test.ts +++ b/packages/host-kit/src/internal/diagnostics.test.ts @@ -7,6 +7,7 @@ import { flushDiagnosticsToSessionFile, registerDiagnosticSensitiveValue, withDiagnosticsScope, + withDiagnosticTimer, } from './diagnostics.ts'; import { mkdtempForTestSync } from './tmp-dir.fixtures.ts'; @@ -174,3 +175,44 @@ test('a later diagnostics scope recreates a removed log directory', async () => mkdirSpy.mockRestore(); } }); + +for (const startEvent of [undefined, 'start']) { + for (const failureKind of ['none', 'throw', 'reject']) { + const fails = failureKind !== 'none'; + test(`diagnostic timer preserves result/error and event contract (start=${startEvent}, failure=${failureKind})`, async () => { + const logPath = path.join(mkdtempForTestSync('diagnostic-timer-'), 'request.ndjson'); + const failure = new Error('fixture phase failure'); + const result = { prepared: true }; + await withDiagnosticsScope({ logPath, flushOnSuccess: true }, async () => { + const timed = withDiagnosticTimer( + 'fixture_phase', + () => { + if (failureKind === 'throw') throw failure; + if (failureKind === 'reject') return Promise.reject(failure); + return Promise.resolve(result); + }, + { timeoutMs: 100 }, + startEvent, + ); + if (fails) await assert.rejects(timed, (error: unknown) => error === failure); + else assert.equal(await timed, result); + flushDiagnosticsToSessionFile(); + }); + const rows = fs + .readFileSync(logPath, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line)); + assert.deepEqual( + rows.map((row) => [row.phase, row.level, row.data.event]), + [ + ...(startEvent ? [['fixture_phase', 'info', 'start']] : []), + ['fixture_phase', fails ? 'error' : 'info', startEvent ? 'settled' : undefined], + ], + ); + assert.equal(rows.at(-1).data.timeoutMs, 100); + assert.ok(rows.at(-1).durationMs >= 0); + assert.equal(rows.at(-1).data.error, fails && !startEvent ? failure.message : undefined); + }); + } +} diff --git a/packages/host-kit/src/internal/diagnostics.ts b/packages/host-kit/src/internal/diagnostics.ts index 94df8f4da5..8d26f95e5f 100644 --- a/packages/host-kit/src/internal/diagnostics.ts +++ b/packages/host-kit/src/internal/diagnostics.ts @@ -38,6 +38,7 @@ type DiagnosticsScopeOptions = { type DiagnosticsScope = DiagnosticsScopeOptions & { diagnosticId: string; + flushedLogPath?: string; events: DiagnosticEvent[]; liveWrittenEventCount: number; // Running per-phase emit tally. Unlike `events`, this is NOT cleared by @@ -173,26 +174,32 @@ export function emitDiagnostic(event: DiagnosticEventInput): void { export async function withDiagnosticTimer( phase: string, fn: () => Promise | T, - data?: Record, + data?: Record | (() => Record), + startEvent?: string, ): Promise { - const start = Date.now(); + const now = startEvent ? () => performance.now() : () => Date.now(); + const start = now(); + const eventData = () => (typeof data === 'function' ? data() : data); + if (startEvent) emitDiagnostic({ phase, data: { ...eventData(), event: startEvent } }); try { const result = await fn(); emitDiagnostic({ level: 'info', phase, - durationMs: Date.now() - start, - data, + durationMs: now() - start, + data: startEvent ? { ...eventData(), event: 'settled' } : eventData(), }); return result; } catch (error) { emitDiagnostic({ level: 'error', phase, - durationMs: Date.now() - start, + durationMs: now() - start, data: { - ...(data ?? {}), - error: error instanceof Error ? error.message : String(error), + ...eventData(), + ...(startEvent + ? { event: 'settled' } + : { error: error instanceof Error ? error.message : String(error) }), }, }); throw error; @@ -220,7 +227,8 @@ export function flushDiagnosticsToSessionFile( const values = sortedScopeSensitiveValues(scope); try { - if (scope.logPath) { + const logPath = scope.logPath ?? scope.flushedLogPath; + if (logPath) { const pendingEvents = scope.events.slice(scope.liveWrittenEventCount); if (pendingEvents.length > 0) { // Data payloads are fully redacted once at emit time; this flush pass @@ -232,12 +240,12 @@ export function flushDiagnosticsToSessionFile( const lines = pendingEvents.map((entry) => JSON.stringify(replaceSensitiveValues(entry, values)), ); - appendDiagnosticLine(scope, scope.logPath, `${lines.join('\n')}\n`); + appendDiagnosticLine(scope, logPath, `${lines.join('\n')}\n`); } const logRecord = scope.logRecord; scope.events = []; scope.liveWrittenEventCount = 0; - return { path: scope.logPath, ...(logRecord ? { ref: logRecord } : {}) }; + return { path: logPath, ...(logRecord ? { ref: logRecord } : {}) }; } const sessionDir = sanitizePathPart(scope.session ?? 'default'); @@ -251,6 +259,7 @@ export function flushDiagnosticsToSessionFile( JSON.stringify(replaceSensitiveValues(entry, values)), ); fs.writeFileSync(filePath, `${lines.join('\n')}\n`); + scope.flushedLogPath = filePath; scope.events = []; return { path: filePath }; } catch { diff --git a/packages/host-kit/src/internal/exec-trace.test.ts b/packages/host-kit/src/internal/exec-trace.test.ts index 7c24aab111..b5accc6212 100644 --- a/packages/host-kit/src/internal/exec-trace.test.ts +++ b/packages/host-kit/src/internal/exec-trace.test.ts @@ -183,40 +183,143 @@ test('background tracing is opt-in and retains a successful completion', async ( }, true, ); - expect(rows.map((row) => row.data.event)).toEqual(['spawn_start', 'spawn', 'settled']); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + 'exit', + 'close', + 'settled', + ]); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); expect(JSON.stringify(rows)).not.toContain('private-argument'); }); -test('environment-only trace persists close after the request finalization flush', async () => { - vi.useFakeTimers(); - const fixture = processFixture(); - const logPath = path.join(mkdtempForTestSync('exec-late-close-'), 'request.ndjson'); - await withCommandHost( - { host: { env: { AGENT_DEVICE_EXEC_TRACE: '1' }, cwd: process.cwd() }, requestEnv: undefined }, - () => - withDiagnosticsScope({ requestId: 'late-close', logPath }, async () => { - const result = runCmd('xcrun', ['simctl', 'list', 'devices', '-j'], { timeoutMs: 100 }); - const rejection = expect(result).rejects.toMatchObject({ code: 'COMMAND_FAILED' }); +for (const fixedLogPath of [true, false]) { + test(`environment-only late close appends to the finalized record (fixedLogPath=${fixedLogPath})`, async () => { + vi.useFakeTimers(); + const fixture = processFixture(); + const home = mkdtempForTestSync('exec-late-close-'); + vi.stubEnv('HOME', home); + const logPath = fixedLogPath ? path.join(home, 'request.ndjson') : undefined; + try { + await withCommandHost( + { + host: { env: { AGENT_DEVICE_EXEC_TRACE: '1' }, cwd: process.cwd() }, + requestEnv: undefined, + }, + () => + withDiagnosticsScope({ requestId: 'late-close', logPath }, async () => { + const result = runCmd('xcrun', ['simctl', 'list', 'devices', '-j'], { timeoutMs: 100 }); + const rejection = expect(result).rejects.toMatchObject({ code: 'COMMAND_FAILED' }); + fixture.child.emit('spawn'); + fixture.exit(0); + await vi.advanceTimersByTimeAsync(100); + await rejection; + const record = flushDiagnosticsToSessionFile({ force: true }); + const filesBefore = fs + .readdirSync(home, { recursive: true }) + .filter((file) => String(file).endsWith('.ndjson')); + await vi.advanceTimersByTimeAsync(1); + fixture.child.emit('close', 0, null); + const filesAfter = fs + .readdirSync(home, { recursive: true }) + .filter((file) => String(file).endsWith('.ndjson')); + expect(filesAfter).toEqual(filesBefore); + const rows = fs + .readFileSync(record?.path ?? path.join(home, String(filesBefore[0])), 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line) as Row); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + 'exit', + 'deadline', + 'settled', + 'close', + ]); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); + }), + ); + } finally { + vi.unstubAllEnvs(); + } + }); +} + +for (const exitBeforeAbort of [false, true]) { + test(`background abort records observed order and settles without close (exitBeforeAbort=${exitBeforeAbort})`, async () => { + const fixture = processFixture(); + const controller = new AbortController(); + const rows = await capture( + false, + async () => { + const { wait } = runCmdBackground('/usr/bin/tool', [], { signal: controller.signal }); + const rejected = expect(wait).rejects.toMatchObject({ code: 'COMMAND_FAILED' }); fixture.child.emit('spawn'); - fixture.exit(0); - await vi.advanceTimersByTimeAsync(100); - await rejection; - flushDiagnosticsToSessionFile(); + if (exitBeforeAbort) fixture.exit(0); + controller.abort(); + if (!exitBeforeAbort) fixture.exit(0); + await rejected; fixture.child.emit('close', 0, null); - const rows = fs - .readFileSync(logPath, 'utf8') - .trim() - .split('\n') - .map((line) => JSON.parse(line) as Row); - expect(rows.map((row) => row.data.event)).toEqual([ - 'spawn_start', - 'spawn', - 'exit', - 'deadline', - 'settled', - 'close', - ]); - expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); - }), - ); -}); + }, + true, + ); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + ...(exitBeforeAbort ? ['exit', 'abort'] : ['abort', 'exit']), + 'settled', + 'close', + ]); + expect(rows.at(-2)?.data.reason).toBe('abort'); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); + expect(fixture.kill).toHaveBeenCalledTimes(exitBeforeAbort ? 0 : 1); + }); +} + +for (const spawnError of [false, true]) { + test(`background completion after scope finalization persists before a late wait (spawnError=${spawnError})`, async () => { + const fixture = processFixture(); + const logPath = path.join(mkdtempForTestSync('exec-background-late-'), 'request.ndjson'); + let complete!: () => void; + const failure = Object.assign(new Error('fixture spawn failure'), { code: 'ENOENT' }); + const { wait, completed } = await withCommandHost( + { + host: { env: { AGENT_DEVICE_EXEC_TRACE: '1' }, cwd: process.cwd() }, + requestEnv: undefined, + }, + () => + withDiagnosticsScope({ logPath }, () => { + const { wait } = runCmdBackground('/usr/bin/tool', []); + const observedWait = wait.then( + (result) => result, + (error: unknown) => error, + ); + if (!spawnError) fixture.child.emit('spawn'); + flushDiagnosticsToSessionFile(); + const completed = new Promise((resolve) => { + complete = resolve; + }).then(() => { + if (spawnError) fixture.child.emit('error', failure); + else fixture.exit(0); + fixture.child.emit('close', spawnError ? -2 : 0, null); + }); + return { wait: observedWait, completed }; + }), + ); + complete(); + await completed; + const rows = fs + .readFileSync(logPath, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line) as Row); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + ...(spawnError ? ['error', 'settled', 'close'] : ['spawn', 'exit', 'close', 'settled']), + ]); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); + expect(await wait).toMatchObject(spawnError ? { code: 'TOOL_MISSING' } : { exitCode: 0 }); + }); +} diff --git a/packages/host-kit/src/internal/exec-trace.ts b/packages/host-kit/src/internal/exec-trace.ts index 769c58547a..62a670bc4f 100644 --- a/packages/host-kit/src/internal/exec-trace.ts +++ b/packages/host-kit/src/internal/exec-trace.ts @@ -1,5 +1,6 @@ import { randomUUID } from 'node:crypto'; import path from 'node:path'; +import { parseBooleanLiteral, type EnvMap } from '@agent-device/kernel/source-value'; import { emitDiagnostic, flushDiagnosticsToSessionFile, @@ -33,10 +34,10 @@ type ExecLifecycleData = { export function createExecTraceContext( cmd: string, - args: readonly string[], timeoutMs: number | undefined, - envTraceEnabled: boolean, + hostEnv: EnvMap | undefined, ): { emit(event: ExecLifecycleEvent, data?: ExecLifecycleData): void } { + const envTraceEnabled = parseBooleanLiteral(hostEnv?.AGENT_DEVICE_EXEC_TRACE ?? '') === true; const meta = getDiagnosticsMeta(); if (!meta.debug && !envTraceEnabled) return { emit: () => {} }; if (envTraceEnabled && !meta.flushOnSuccess) updateDiagnosticsScope({ flushOnSuccess: true }); @@ -45,24 +46,18 @@ export function createExecTraceContext( let pid: number | undefined; let settlementEmitted = false; const command = path.basename(cmd); - const simctlArgs = args[1] === '--set' ? args.slice(3) : args.slice(1); - const operation = - command === 'xcrun' && - args[0] === 'simctl' && - simctlArgs.length === 3 && - simctlArgs.join(' ') === 'list devices -j' - ? 'simctl_list_devices' - : undefined; const emit = (event: ExecLifecycleEvent, data: ExecLifecycleData = {}): void => { pid = data.pid ?? pid; emitDiagnostic({ level: 'debug', phase: 'exec_command', durationMs: performance.now() - started, - data: { execId, command, operation, event, pid, timeoutMs, ...data }, + data: { execId, command, event, pid, timeoutMs, ...data }, }); if (event === 'settled') settlementEmitted = true; - if (event === 'close' && settlementEmitted && envTraceEnabled) flushDiagnosticsToSessionFile(); + if (envTraceEnabled && (event === 'settled' || (event === 'close' && settlementEmitted))) { + flushDiagnosticsToSessionFile(); + } }; emit('spawn_start'); return { emit }; diff --git a/packages/host-kit/src/internal/exec.ts b/packages/host-kit/src/internal/exec.ts index 1ad60f541b..181bd7b1a3 100644 --- a/packages/host-kit/src/internal/exec.ts +++ b/packages/host-kit/src/internal/exec.ts @@ -7,11 +7,7 @@ import { Readable } from 'node:stream'; import { pipeline } from 'node:stream/promises'; import { AppError, createRequestCanceledError } from '@agent-device/kernel/errors'; import { createExecTraceContext, type ExecSettlementReason } from './exec-trace.ts'; -import { - parseBooleanLiteral, - type EnvMap, - type HostEnvironment, -} from '@agent-device/kernel/source-value'; +import type { EnvMap, HostEnvironment } from '@agent-device/kernel/source-value'; export type ExecResult = { stdout: string; @@ -209,10 +205,8 @@ function runSpawnedCommand( const executable = normalizeExecutableCommand(cmd); const execTrace = createExecTraceContext( cmd, - args, normalizeTimeoutMs(options.timeoutMs), - parseBooleanLiteral(commandHostScope.getStore()?.host.env.AGENT_DEVICE_EXEC_TRACE ?? '') === - true, + commandHostScope.getStore()?.host.env, ); return new Promise((resolve, reject) => { const child = spawn(executable, args, { @@ -503,13 +497,7 @@ export function runCmdBackground( options: ExecBackgroundOptions = {}, ): ExecBackgroundResult { const executable = normalizeExecutableCommand(cmd); - const execTrace = createExecTraceContext( - cmd, - args, - undefined, - parseBooleanLiteral(commandHostScope.getStore()?.host.env.AGENT_DEVICE_EXEC_TRACE ?? '') === - true, - ); + const execTrace = createExecTraceContext(cmd, undefined, commandHostScope.getStore()?.host.env); const child = spawn(executable, args, { cwd: options.cwd, env: resolveSpawnEnv(options.env), @@ -578,12 +566,22 @@ export function runCmdBackground( killProcessTree: () => killProcessTree(child, options), settle, }); - const abort = watchCommandAbort(options, settlement.requestKill); + const abort = watchCommandAbort(options, () => { + execTrace.emit('abort'); + settlement.requestKill(); + }); child.on('error', (err) => { + execTrace.emit('error'); if (finish('error')) reject(spawnRejectionError(abort, executable, cmd, args, err)); }); - child.once('exit', settlement.recordExit); - child.once('close', settle); + child.once('exit', (code, signal) => { + execTrace.emit('exit', { exitCode: code, signal }); + settlement.recordExit(code); + }); + child.once('close', (code, signal) => { + execTrace.emit('close', { exitCode: code, signal }); + settle(code); + }); }); return { child, wait }; diff --git a/packages/platform-apple/src/lifecycle.ts b/packages/platform-apple/src/lifecycle.ts index f530586e2a..c394c9ad8e 100644 --- a/packages/platform-apple/src/lifecycle.ts +++ b/packages/platform-apple/src/lifecycle.ts @@ -1,4 +1,4 @@ -import { emitDiagnostic } from '@agent-device/host-kit/diagnostics'; +import { emitDiagnostic, withDiagnosticTimer } from '@agent-device/host-kit/diagnostics'; import { type ApplicationLifecycleRuntimeOperations, type AppleRunnerSessionPrewarmOptions, @@ -460,26 +460,30 @@ async function prepareAppleRunner( // the runner preparation gets what is left rather than the full budget again. const deadlineAtMs = Date.now() + input.timeoutMs; const traceStarted = performance.now(); - const trace = (event: 'readiness_start' | 'runner_start' | 'settled') => - emitDiagnostic({ - phase: 'prepare_apple_runner', - durationMs: performance.now() - traceStarted, - data: { event, timeoutMs: input.timeoutMs, remainingMs: deadlineAtMs - Date.now() }, - }); - trace('readiness_start'); - try { - const readied = await ensureAppleReady(host, device, signal, { deadlineAtMs }); - const timeoutMs = Math.max(1, deadlineAtMs - Date.now()); - trace('runner_start'); - const prepared = await host.appleApplications.prepareRunner( - readied, - { ...input, timeoutMs }, - signal, - ); - return { readied, prepared }; - } finally { - trace('settled'); - } + return await withDiagnosticTimer( + 'prepare_apple_runner', + async () => { + const readied = await ensureAppleReady(host, device, signal, { deadlineAtMs }); + const timeoutMs = Math.max(1, deadlineAtMs - Date.now()); + emitDiagnostic({ + phase: 'prepare_apple_runner', + durationMs: performance.now() - traceStarted, + data: { + event: 'runner_start', + timeoutMs: input.timeoutMs, + remainingMs: deadlineAtMs - Date.now(), + }, + }); + const prepared = await host.appleApplications.prepareRunner( + readied, + { ...input, timeoutMs }, + signal, + ); + return { readied, prepared }; + }, + () => ({ timeoutMs: input.timeoutMs, remainingMs: deadlineAtMs - Date.now() }), + 'readiness_start', + ); } type RunnerPrewarm = Readonly<{ diff --git a/packages/platform-apple/src/simulator-state.ts b/packages/platform-apple/src/simulator-state.ts index 83ae2e6b2b..fb76c78d36 100644 --- a/packages/platform-apple/src/simulator-state.ts +++ b/packages/platform-apple/src/simulator-state.ts @@ -1,4 +1,4 @@ -import { emitDiagnostic } from '@agent-device/host-kit/diagnostics'; +import { withDiagnosticTimer } from '@agent-device/host-kit/diagnostics'; import type { DeviceInfo } from '@agent-device/kernel/device'; import type { AppleToolHost } from '@agent-device/contracts/platform-runtime-host'; import { readSimctlDeviceState, scopeSimctlArgsForDevice } from './core/simctl.ts'; @@ -9,25 +9,22 @@ export async function getSimulatorState( signal: AbortSignal, timeoutMs: number, ): Promise { - const started = performance.now(); - emitDiagnostic({ phase: 'simulator_state', data: { event: 'start', timeoutMs } }); - try { - const result = await appleTools.run( - { - tool: 'simctl', - args: scopeSimctlArgsForDevice(device, ['list', 'devices', '-j']), - allowFailure: true, - timeoutMs, - }, - signal, - ); - if (result.exitCode !== 0) return null; - return readSimctlDeviceState(result.stdout, device.id); - } finally { - emitDiagnostic({ - phase: 'simulator_state', - durationMs: performance.now() - started, - data: { event: 'settled', timeoutMs }, - }); - } + return await withDiagnosticTimer( + 'simulator_state', + async () => { + const result = await appleTools.run( + { + tool: 'simctl', + args: scopeSimctlArgsForDevice(device, ['list', 'devices', '-j']), + allowFailure: true, + timeoutMs, + }, + signal, + ); + if (result.exitCode !== 0) return null; + return readSimctlDeviceState(result.stdout, device.id); + }, + { timeoutMs }, + 'start', + ); } From 84ef0ba88ab0a98a66627314e329e833e5b7bcac Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Tue, 20 Oct 2026 16:46:21 +0200 Subject: [PATCH 4/4] fix(diagnostics): retain originating scope during cancellation --- .../host-kit/src/internal/exec-trace.test.ts | 75 ++++++++++++------- packages/host-kit/src/internal/exec-trace.ts | 29 +++---- 2 files changed, 62 insertions(+), 42 deletions(-) diff --git a/packages/host-kit/src/internal/exec-trace.test.ts b/packages/host-kit/src/internal/exec-trace.test.ts index b5accc6212..1657912904 100644 --- a/packages/host-kit/src/internal/exec-trace.test.ts +++ b/packages/host-kit/src/internal/exec-trace.test.ts @@ -247,35 +247,52 @@ for (const fixedLogPath of [true, false]) { }); } -for (const exitBeforeAbort of [false, true]) { - test(`background abort records observed order and settles without close (exitBeforeAbort=${exitBeforeAbort})`, async () => { - const fixture = processFixture(); - const controller = new AbortController(); - const rows = await capture( - false, - async () => { - const { wait } = runCmdBackground('/usr/bin/tool', [], { signal: controller.signal }); - const rejected = expect(wait).rejects.toMatchObject({ code: 'COMMAND_FAILED' }); - fixture.child.emit('spawn'); - if (exitBeforeAbort) fixture.exit(0); - controller.abort(); - if (!exitBeforeAbort) fixture.exit(0); - await rejected; - fixture.child.emit('close', 0, null); - }, - true, - ); - expect(rows.map((row) => row.data.event)).toEqual([ - 'spawn_start', - 'spawn', - ...(exitBeforeAbort ? ['exit', 'abort'] : ['abort', 'exit']), - 'settled', - 'close', - ]); - expect(rows.at(-2)?.data.reason).toBe('abort'); - expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); - expect(fixture.kill).toHaveBeenCalledTimes(exitBeforeAbort ? 0 : 1); - }); +for (const background of [false, true]) { + for (const exitBeforeAbort of [false, true]) { + test(`cancellation outside request scope retains order and correlation (background=${background}, exitBeforeAbort=${exitBeforeAbort})`, async () => { + const fixture = processFixture(); + const controller = new AbortController(); + const logPath = path.join(mkdtempForTestSync('exec-external-abort-'), 'request.ndjson'); + const { wait } = await withCommandHost( + { + host: { env: { AGENT_DEVICE_EXEC_TRACE: '1' }, cwd: process.cwd() }, + requestEnv: undefined, + }, + () => + withDiagnosticsScope({ requestId: 'origin-request', logPath }, () => { + const options = { signal: controller.signal }; + const pending = background + ? runCmdBackground('/usr/bin/tool', [], options).wait + : runCmd('/usr/bin/tool', [], options); + const wait = pending.catch((error: unknown) => error); + fixture.child.emit('spawn'); + if (exitBeforeAbort) fixture.exit(0); + flushDiagnosticsToSessionFile(); + return { wait }; + }), + ); + controller.abort(); + if (!exitBeforeAbort) fixture.exit(0); + expect(await wait).toMatchObject({ code: 'COMMAND_FAILED' }); + fixture.child.emit('close', 0, null); + const rows = fs + .readFileSync(logPath, 'utf8') + .trim() + .split('\n') + .map((line) => JSON.parse(line) as Row); + expect(rows.map((row) => row.data.event)).toEqual([ + 'spawn_start', + 'spawn', + ...(exitBeforeAbort ? ['exit', 'abort'] : ['abort', 'exit']), + 'settled', + 'close', + ]); + expect(rows.at(-2)?.data.reason).toBe('abort'); + expect(rows.every((row) => row.requestId === 'origin-request')).toBe(true); + expect(new Set(rows.map((row) => row.data.execId)).size).toBe(1); + expect(fixture.kill).toHaveBeenCalledTimes(exitBeforeAbort ? 0 : 1); + }); + } } for (const spawnError of [false, true]) { diff --git a/packages/host-kit/src/internal/exec-trace.ts b/packages/host-kit/src/internal/exec-trace.ts index 62a670bc4f..3a0ca05526 100644 --- a/packages/host-kit/src/internal/exec-trace.ts +++ b/packages/host-kit/src/internal/exec-trace.ts @@ -1,3 +1,4 @@ +import { AsyncLocalStorage } from 'node:async_hooks'; import { randomUUID } from 'node:crypto'; import path from 'node:path'; import { parseBooleanLiteral, type EnvMap } from '@agent-device/kernel/source-value'; @@ -46,19 +47,21 @@ export function createExecTraceContext( let pid: number | undefined; let settlementEmitted = false; const command = path.basename(cmd); - const emit = (event: ExecLifecycleEvent, data: ExecLifecycleData = {}): void => { - pid = data.pid ?? pid; - emitDiagnostic({ - level: 'debug', - phase: 'exec_command', - durationMs: performance.now() - started, - data: { execId, command, event, pid, timeoutMs, ...data }, - }); - if (event === 'settled') settlementEmitted = true; - if (envTraceEnabled && (event === 'settled' || (event === 'close' && settlementEmitted))) { - flushDiagnosticsToSessionFile(); - } - }; + const emit = AsyncLocalStorage.bind( + (event: ExecLifecycleEvent, data: ExecLifecycleData = {}): void => { + pid = data.pid ?? pid; + emitDiagnostic({ + level: 'debug', + phase: 'exec_command', + durationMs: performance.now() - started, + data: { execId, command, event, pid, timeoutMs, ...data }, + }); + if (event === 'settled') settlementEmitted = true; + if (envTraceEnabled && (event === 'settled' || (event === 'close' && settlementEmitted))) { + flushDiagnosticsToSessionFile(); + } + }, + ); emit('spawn_start'); return { emit }; }