diff --git a/packages/platform-apple/src/logs/runtime.fixtures.ts b/packages/platform-apple/src/logs/runtime.fixtures.ts index 1201be6709..b9924dde81 100644 --- a/packages/platform-apple/src/logs/runtime.fixtures.ts +++ b/packages/platform-apple/src/logs/runtime.fixtures.ts @@ -25,6 +25,8 @@ export function appleDevice(overrides: Partial = {}): DeviceInfo { export function hostFixture( options: { failProcessStart?: boolean; + startProcess?: AppLogRuntimeHost['processes']['start']; + sleep?: AppLogRuntimeHost['clock']['sleep']; commandRun?: AppLogRuntimeHost['commands']['run']; appleToolRun?: AppLogRuntimeHost['appleTools']['run']; } = {}, @@ -33,10 +35,12 @@ export function hostFixture( let outputDisposed = false; let outputOpens = 0; let markerReads = 0; - const startProcess: AppLogRuntimeHost['processes']['start'] = vi.fn(async ({ command }) => { + const startProcess: AppLogRuntimeHost['processes']['start'] = vi.fn(async (request, signal) => { + const { command } = request; if (command.kind !== 'host') throw new Error('Expected an Apple host command'); backgroundCommands.push([command.request.executable, ...command.request.args]); if (options.failProcessStart) throw new Error('start failed'); + if (options.startProcess) return await options.startProcess(request, signal); return { wait: new Promise(() => {}), terminate: async () => {}, @@ -87,7 +91,7 @@ export function hostFixture( inspect: async () => 'missing', terminate: async () => 'already-missing', }, - clock: { now: () => 10, sleep: async () => {} }, + clock: { now: () => 10, sleep: options.sleep ?? (async () => {}) }, }; return { host, diff --git a/packages/platform-apple/src/logs/start.test.ts b/packages/platform-apple/src/logs/start.test.ts index 835cf866a7..7064190838 100644 --- a/packages/platform-apple/src/logs/start.test.ts +++ b/packages/platform-apple/src/logs/start.test.ts @@ -1,3 +1,4 @@ +import type { AppLogOutputSink, AppLogRuntimeHost } from '@agent-device/contracts/app-log-runtime'; import { localRuntimeOwner } from '@agent-device/contracts/platform-runtime'; import { expect, test, vi } from 'vitest'; import { startAppleAppLogs } from './start.ts'; @@ -91,3 +92,122 @@ test('simulator log stream takes the set of the device it streams from', async ( 'stream', ]); }); + +test('simulator start returns only after the in-simulator stream writes output', async () => { + const stream = launchingStream(); + const fixture = hostFixture({ startProcess: stream.start, sleep: sleepUntilAborted }); + + const starting = startAppleAppLogs( + fixture.host, + appleDevice(), + startInput(), + localRuntimeOwner('apple'), + ); + await vi.waitFor(() => expect(stream.output()).toBeDefined()); + await expect(settlesSoon(starting)).resolves.toBe(false); + + await stream.output()!.write('Filtering the log data\n'); + + await expect(starting).resolves.toMatchObject({ envelope: expect.anything() }); +}); + +test('simulator start returns when the stream exits before writing output', async () => { + const stream = launchingStream({ exited: true }); + const fixture = hostFixture({ startProcess: stream.start, sleep: sleepUntilAborted }); + + await expect( + startAppleAppLogs(fixture.host, appleDevice(), startInput(), localRuntimeOwner('apple')), + ).resolves.toMatchObject({ envelope: expect.anything() }); +}); + +test('simulator start fails with a typed reason when the stream does not launch in time', async () => { + const stream = launchingStream(); + const fixture = hostFixture({ startProcess: stream.start }); + + await expect( + startAppleAppLogs(fixture.host, appleDevice(), startInput(), localRuntimeOwner('apple')), + ).rejects.toMatchObject({ + code: 'COMMAND_FAILED', + details: { reason: 'simulator-log-stream-launch-timeout' }, + }); + expect(stream.disposed()).toBe(true); + expect(fixture.outputDisposed()).toBe(true); +}); + +test('host log stream start does not wait for output', async () => { + const stream = launchingStream(); + const fixture = hostFixture({ startProcess: stream.start, sleep: sleepUntilAborted }); + + await expect( + startAppleAppLogs( + fixture.host, + appleDevice({ appleOs: 'macos', kind: 'device' }), + startInput(), + localRuntimeOwner('apple'), + ), + ).resolves.toMatchObject({ envelope: expect.anything() }); +}); + +test('simulator start cancelled before the stream launches terminates the process', async () => { + const stream = launchingStream(); + const fixture = hostFixture({ startProcess: stream.start, sleep: sleepUntilAborted }); + const controller = new AbortController(); + const reason = new Error('request cancelled'); + + const starting = startAppleAppLogs( + fixture.host, + appleDevice(), + startInput(), + localRuntimeOwner('apple'), + controller.signal, + ); + await vi.waitFor(() => expect(stream.output()).toBeDefined()); + controller.abort(reason); + + await expect(starting).rejects.toBe(reason); + expect(stream.disposed()).toBe(true); + expect(fixture.outputDisposed()).toBe(true); +}); + +function startInput() { + return { + sessionId: 'session', + appBundleId: 'com.example.app', + outputPath: '/tmp/app.log', + fence: { token: 'fence', generation: 1 }, + }; +} + +function launchingStream(options: { exited?: boolean } = {}) { + let output: AppLogOutputSink | undefined; + let disposed = false; + const start: AppLogRuntimeHost['processes']['start'] = async (request) => { + output = request.output; + return { + wait: options.exited + ? Promise.resolve({ stdout: '', stderr: '', exitCode: 1 }) + : new Promise(() => {}), + terminate: async () => {}, + [Symbol.asyncDispose]: async () => { + disposed = true; + }, + }; + }; + return { start, output: () => output, disposed: () => disposed }; +} + +async function sleepUntilAborted(_milliseconds: number, signal?: AbortSignal): Promise { + await new Promise((_resolve, reject) => { + signal?.addEventListener('abort', () => reject(signal.reason), { once: true }); + }); +} + +async function settlesSoon(promise: Promise): Promise { + let settled = false; + void promise.then( + () => (settled = true), + () => (settled = true), + ); + for (let turn = 0; turn < 10; turn += 1) await new Promise((resolve) => setImmediate(resolve)); + return settled; +} diff --git a/packages/platform-apple/src/logs/start.ts b/packages/platform-apple/src/logs/start.ts index 4c41375636..1460a25270 100644 --- a/packages/platform-apple/src/logs/start.ts +++ b/packages/platform-apple/src/logs/start.ts @@ -4,6 +4,7 @@ import { AppError } from '@agent-device/kernel/errors'; import type { AppLogBackgroundProcess, AppLogLiveSnapshot, + AppLogOutputSink, AppLogRuntimeHost, AppLogStartInput, AppLogStartResult, @@ -31,6 +32,9 @@ import { buildIosSimulatorLogStreamArgs, } from './log-predicate.ts'; +// Measured launches take 1-2 s on a loaded host. +const SIMULATOR_STREAM_LAUNCH_TIMEOUT_MS = 10_000; + export async function startAppleAppLogs( host: AppLogRuntimeHost, device: DeviceInfo, @@ -50,17 +54,21 @@ export async function startAppleAppLogs( if (!adopted) await output[Symbol.asyncDispose](); }); signal?.throwIfAborted(); + const launch = observeFirstWrite(output); const backgroundProcess = await startCheckedAppleProcess( host, device, command, - output, + launch.sink, input.pidPath, signal, ); rollback.defer(async () => { if (!adopted) await backgroundProcess[Symbol.asyncDispose](); }); + if (device.kind === 'simulator') { + await waitForSimulatorStreamLaunch(host, launch.written, backgroundProcess.wait, signal); + } const handle = createAppleProcessHandle( host, backgroundProcess, @@ -110,7 +118,7 @@ async function startCheckedAppleProcess( host: AppLogRuntimeHost, device: DeviceInfo, command: { executable: string; args: readonly string[]; allowFailure: true }, - output: Awaited>, + output: AppLogOutputSink, pidPath: string | undefined, signal?: AbortSignal, ): Promise { @@ -193,10 +201,70 @@ async function resolveSimulatorExecutable( return plist.exitCode === 0 ? plist.stdout.trim() || undefined : undefined; } +function observeFirstWrite(output: AppLogOutputSink): { + sink: AppLogOutputSink; + written: Promise; +} { + let markWritten = noop; + const written = new Promise((resolve) => { + markWritten = resolve; + }); + const sink: AppLogOutputSink = { + write: async (chunk) => { + markWritten(); + await output.write(chunk); + }, + [Symbol.asyncDispose]: async () => await output[Symbol.asyncDispose](), + }; + return { sink, written }; +} + +// simctl forwards a stop signal only after the in-simulator process has launched. An earlier +// signal ends simctl while the launch completes, and the orphan keeps the output pipes open. +async function waitForSimulatorStreamLaunch( + host: AppLogRuntimeHost, + written: Promise, + exited: Promise, + signal?: AbortSignal, +): Promise { + signal?.throwIfAborted(); + let onAbort = noop; + const aborted = new Promise((_resolve, reject) => { + onAbort = () => reject(signal?.reason); + signal?.addEventListener('abort', onAbort, { once: true }); + }); + const deadline = new AbortController(); + const timedOut = host.clock + .sleep(SIMULATOR_STREAM_LAUNCH_TIMEOUT_MS, deadline.signal) + .then(() => 'timed-out' as const); + timedOut.catch(noop); + try { + const launched = Promise.race([written, exited.then(noop, noop)]).then( + () => 'launched' as const, + ); + if ((await Promise.race([launched, timedOut, aborted])) === 'timed-out') { + throw new AppError( + 'COMMAND_FAILED', + `Simulator log stream did not start within ${SIMULATOR_STREAM_LAUNCH_TIMEOUT_MS}ms`, + { + reason: 'simulator-log-stream-launch-timeout', + timeoutMs: SIMULATOR_STREAM_LAUNCH_TIMEOUT_MS, + hint: 'Check that the simulator finished booting, then retry logs start.', + }, + ); + } + } finally { + deadline.abort(); + signal?.removeEventListener('abort', onAbort); + } +} + +function noop(): void {} + function createAppleProcessHandle( host: AppLogRuntimeHost, backgroundProcess: AppLogBackgroundProcess, - output: Awaited>, + output: AppLogOutputSink, backend: LogBackend, outputPath: string, ) { diff --git a/src/platform-runtime-app-log-process.test.ts b/src/platform-runtime-app-log-process.test.ts index 937937d31c..5f28044809 100644 --- a/src/platform-runtime-app-log-process.test.ts +++ b/src/platform-runtime-app-log-process.test.ts @@ -181,6 +181,48 @@ describe('managed app-log process host', () => { expect(fixture.child.kill).toHaveBeenCalledWith('SIGINT'); }); + test('terminate settles when an escaped descendant keeps the output pipes open', async () => { + const { runCmdBackground } = await vi.importActual< + typeof import('@agent-device/host-kit/command') + >('@agent-device/host-kit/command'); + const fixture = processFixture(); + let launched: ReturnType | undefined; + exec.run.mockImplementation((...args: Parameters) => { + launched = runCmdBackground(...args); + return launched; + }); + // SIGINT reaches only the direct child; the background loop keeps the inherited pipes open, + // like a log process that simctl launched inside the simulator. + let ticks = 0; + const running = await createManagedAppLogProcesses(fixture.sessionsDir, process.env).start({ + ...fixture.request, + output: { ...fixture.request.output, write: async () => void (ticks += 1) }, + command: { + kind: 'host', + request: { + executable: 'sh', + args: ['-c', '(while echo tick; do sleep 0.1; done) & exec sleep 30'], + allowFailure: true, + }, + }, + }); + await vi.waitFor(() => expect(ticks).toBeGreaterThan(0)); + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + try { + let terminated = false; + void running.terminate().then(() => (terminated = true)); + await vi.waitFor(() => expect(launched?.child.signalCode).toBe('SIGINT')); + + await vi.advanceTimersByTimeAsync(4_000); + + await vi.waitFor(() => expect(terminated).toBe(true)); + await expect(running.wait).resolves.toMatchObject({ exitCode: 1 }); + expect(fs.existsSync(fixture.markerPath)).toBe(false); + } finally { + vi.useRealTimers(); + } + }); + test('retains a marker that is corrupted before the managed child exits', async () => { const fixture = processFixture(); const running = await createManagedAppLogProcesses(fixture.sessionsDir, process.env).start( diff --git a/src/platform-runtime-app-log-process.ts b/src/platform-runtime-app-log-process.ts index 4a7f1516a4..0201739a94 100644 --- a/src/platform-runtime-app-log-process.ts +++ b/src/platform-runtime-app-log-process.ts @@ -15,6 +15,7 @@ import type { DeviceIdentity } from '@agent-device/kernel/device'; import type { EnvMap } from '@agent-device/kernel/source-value'; import fs from 'node:fs'; import path from 'node:path'; +import type { Readable } from 'node:stream'; import { openVerifiedFileForRead } from '@agent-device/host-kit/file'; import { runCmdBackground } from '@agent-device/host-kit/command'; import { @@ -31,8 +32,8 @@ const APP_LOG_PID_FILENAME = 'app-log.pid'; type ManagedAppLogCommandChild = Readonly<{ pid?: number; exitCode?: number | null; - stdout?: NodeJS.ReadableStream | null; - stderr?: NodeJS.ReadableStream | null; + stdout?: Readable | null; + stderr?: Readable | null; kill(signal?: NodeJS.Signals | number): boolean; }>; @@ -248,9 +249,16 @@ function createManagedProcessTermination( let termination: Promise | undefined; return async () => await (termination ??= (async () => { - if (typeof child.exitCode === 'number') return; - child.kill('SIGINT'); - if (!(await settlesWithin(wait, 2_000))) child.kill('SIGKILL'); + if (typeof child.exitCode !== 'number') { + child.kill('SIGINT'); + if (!(await settlesWithin(wait, 2_000))) child.kill('SIGKILL'); + } + // A process outside the child's tree, such as one launched inside a simulator, can keep the + // output pipes open after the child exits. Releasing them lets the wait settle on that exit. + if (!(await settlesWithin(wait, 2_000))) { + child.stdout?.destroy(); + child.stderr?.destroy(); + } await wait.catch(() => undefined); })()); } diff --git a/website/docs/docs/commands.md b/website/docs/docs/commands.md index 68a609bf9a..4371164a64 100644 --- a/website/docs/docs/commands.md +++ b/website/docs/docs/commands.md @@ -1062,7 +1062,7 @@ agent-device network dump 25 --include headers --platform web # Browser requests ``` - `logs` works on iOS simulators, iOS physical devices, Android, and macOS (app-scoped Unified Logging). On iOS, capture relies on Unified Logging (`os_log`); plain stdout/stderr may be limited. -- `logs start` appends to `app.log` and rotates at 5 MB. Override with `AGENT_DEVICE_APP_LOG_MAX_BYTES` and `AGENT_DEVICE_APP_LOG_MAX_FILES`; set `AGENT_DEVICE_APP_LOG_REDACT_PATTERNS` to a comma-separated regex list for write-time redaction. +- `logs start` appends to `app.log` and rotates at 5 MB. Override with `AGENT_DEVICE_APP_LOG_MAX_BYTES` and `AGENT_DEVICE_APP_LOG_MAX_FILES`; set `AGENT_DEVICE_APP_LOG_REDACT_PATTERNS` to a comma-separated regex list for write-time redaction. On Apple simulators, `logs start` returns once the simulator log stream is running, so lines that the app logs after that are captured. If the stream does not start within 10 s, `logs start` fails with `details.reason: "simulator-log-stream-launch-timeout"`. - `open` prints `Session state: `; see [Sessions](/docs/sessions#find-a-sessions-logs-and-artifacts) for the files it contains. - `events` reads the session timeline, which leaves out user-entered content; `--no-record` suppresses `action.recorded` entries. `events.ndjson` rotates at 5 MB (`AGENT_DEVICE_EVENT_LOG_MAX_BYTES`) and keeps one generation. Cursors stay valid across rotation; a cursor older than the retained window fails with `details.reason: "EVENT_LOG_CURSOR_EXPIRED"` and `details.earliestCursor`. If the retained files were edited or deleted, `events` fails with `details.reason: "EVENT_LOG_WINDOW_UNVERIFIED"`. - `network dump [limit] [summary|headers|body|all]` parses recent HTTP(s) entries from `app.log`, or from managed `agent-browser` request history on web; `network log` is an alias. Prefer `--include` over the positional detail level. It scans up to 4000 log lines, returns up to 200 entries, and truncates fields at 2048 characters. Web does not expose bodies.