From cec2a8004fc94ea3d1dd78bfe2faa5fe4c049f28 Mon Sep 17 00:00:00 2001 From: Gabe Debes Date: Fri, 9 Oct 2026 01:18:09 -0700 Subject: [PATCH] [build-tools] Stream preview output in the existing session step --- .changeset/serve-sim-web-preview-logs.md | 5 + .../src/steps/functions/startLocalEgress.ts | 1 + .../utils/__tests__/deviceSessionHost.test.ts | 50 +++++- .../steps/utils/__tests__/localEgress.test.ts | 23 ++- .../utils/__tests__/processOutput.test.ts | 139 ++++++++++++++++ .../__tests__/processOutputProcess.test.ts | 156 ++++++++++++++++++ .../__tests__/remoteDeviceRunSession.test.ts | 65 +++++++- .../__tests__/serveSimLogsRecorder.test.ts | 17 +- .../src/steps/utils/deviceSessionHost.ts | 8 + .../src/steps/utils/localEgress.ts | 8 +- .../src/steps/utils/processOutput.ts | 88 ++++++++++ .../src/steps/utils/remoteDeviceRunSession.ts | 66 +++++--- 12 files changed, 591 insertions(+), 35 deletions(-) create mode 100644 .changeset/serve-sim-web-preview-logs.md create mode 100644 packages/build-tools/src/steps/utils/__tests__/processOutput.test.ts create mode 100644 packages/build-tools/src/steps/utils/__tests__/processOutputProcess.test.ts create mode 100644 packages/build-tools/src/steps/utils/processOutput.ts diff --git a/.changeset/serve-sim-web-preview-logs.md b/.changeset/serve-sim-web-preview-logs.md new file mode 100644 index 0000000000..4b8f781d3e --- /dev/null +++ b/.changeset/serve-sim-web-preview-logs.md @@ -0,0 +1,5 @@ +--- +'@expo/build-tools': minor +--- + +Stream simulator preview output into its existing session step. diff --git a/packages/build-tools/src/steps/functions/startLocalEgress.ts b/packages/build-tools/src/steps/functions/startLocalEgress.ts index 5c504c9aa0..e03cb8321b 100644 --- a/packages/build-tools/src/steps/functions/startLocalEgress.ts +++ b/packages/build-tools/src/steps/functions/startLocalEgress.ts @@ -156,6 +156,7 @@ export function createStartLocalEgressBuildFunction(): BuildFunction { controlPort, authfilePath, env, + logger, signal: startupSignal, }); server = started.process; diff --git a/packages/build-tools/src/steps/utils/__tests__/deviceSessionHost.test.ts b/packages/build-tools/src/steps/utils/__tests__/deviceSessionHost.test.ts index d586fbe0ce..0e4bc6c7a9 100644 --- a/packages/build-tools/src/steps/utils/__tests__/deviceSessionHost.test.ts +++ b/packages/build-tools/src/steps/utils/__tests__/deviceSessionHost.test.ts @@ -17,7 +17,11 @@ import { startDeviceRunSessionPreview, } from '../deviceRunSessionPreview'; import { startDeviceSessionHostAsync } from '../deviceSessionHost'; -import { ensureFfmpegInstalledOnceAsync, spawnDetached } from '../remoteDeviceRunSession'; +import { + ensureFfmpegInstalledOnceAsync, + fetchWebPreviewTurnArgsAsync, + spawnDetached, +} from '../remoteDeviceRunSession'; jest.mock('@ngrok/ngrok'); jest.mock('../deviceRunSessionArtifacts'); @@ -574,3 +578,47 @@ it('keeps the session running when encoder setup for the preview fails', async ( ); await host.finishAsync(); }); + +it('adds the iOS preview token to the host secrets once serve-sim is ready', async () => { + jest + .mocked(fetchWebPreviewTurnArgsAsync) + .mockResolvedValueOnce(['--turn-credential', 'turn-secret']); + let secretsAtSpawn: string[] | undefined; + jest.mocked(spawnDetached).mockImplementationOnce(options => { + secretsAtSpawn = [...(options.secrets ?? [])]; + return { + pid: undefined, + getOutput: () => '', + getExitError: () => undefined, + stopAsync: stopServer, + }; + }); + const host = await startDeviceSessionHostAsync(ctx, { + runtimePlatform: BuildRuntimePlatform.DARWIN, + env, + logger, + timeoutMs: 10_000, + }); + expect(secretsAtSpawn).toEqual(['turn-secret']); + // Host output is redacted against this array, so the token must land in the one passed at spawn. + expect(jest.mocked(spawnDetached).mock.calls[0][0].secrets).toEqual([ + 'turn-secret', + 'preview-token', + ]); + expect((await host.openPreviewAsync({ baseDomain })).previewToken).toBe('preview-token'); + await host.finishAsync(); +}); + +it('uses the existing step logger for startup and shutdown output', async () => { + const host = await startHostAsync(); + const processLogger = jest.mocked(spawnDetached).mock.calls[0][0].logger; + expect(processLogger).toBe(logger); + stopServer.mockImplementationOnce(async () => processLogger?.info('last host output')); + await host.finishAsync(); + expect(logger.info).toHaveBeenCalledWith('last host output'); + expect( + jest + .mocked(logger.info) + .mock.calls.some(([record]) => typeof record === 'object' && 'marker' in record) + ).toBe(false); +}); diff --git a/packages/build-tools/src/steps/utils/__tests__/localEgress.test.ts b/packages/build-tools/src/steps/utils/__tests__/localEgress.test.ts index a3aa29c4bc..5d0bf3fd29 100644 --- a/packages/build-tools/src/steps/utils/__tests__/localEgress.test.ts +++ b/packages/build-tools/src/steps/utils/__tests__/localEgress.test.ts @@ -437,11 +437,13 @@ describe(configureSimulatorProxyEnvironmentAsync, () => { }); describe(startChiselServerAsync, () => { + const logger = { warn: jest.fn() } as unknown as bunyan; const options = { chiselPath: '/tmp/chisel', controlPort: 52001, authfilePath: '/tmp/authfile.json', env: { PATH: '/bin', AUTH: 'unexpected:password' }, + logger, }; let output: string; let stopAsync: jest.Mock; @@ -483,7 +485,9 @@ describe(startChiselServerAsync, () => { expect(stopAsync).not.toHaveBeenCalled(); }); - it('rejects and stops a child that prints its fingerprint then fails to bind', async () => { + it('keeps the bind error and warns when a child that failed to bind cannot be stopped', async () => { + const stopError = new Error('drain timed out'); + stopAsync.mockRejectedValueOnce(stopError); const started = startChiselServerAsync(options); const rejected = expect(started).rejects.toThrow('address already in use'); output += 'listen tcp 127.0.0.1:52001: bind: address already in use\n'; @@ -493,16 +497,27 @@ describe(startChiselServerAsync, () => { await jest.advanceTimersByTimeAsync(250); await rejected; expect(stopAsync).toHaveBeenCalledTimes(1); + expect(logger.warn).toHaveBeenCalledWith( + { err: stopError }, + 'Could not stop the reverse tunnel server after it failed to start.' + ); }); - it('stops the child when startup is cancelled', async () => { + it('keeps the cancellation and warns when the cancelled child cannot be stopped', async () => { + const stopError = new Error('drain timed out'); + stopAsync.mockRejectedValueOnce(stopError); const controller = new AbortController(); + const cancelled = new Error('cancelled'); const started = startChiselServerAsync({ ...options, signal: controller.signal }); - const rejected = expect(started).rejects.toThrow('cancelled'); - controller.abort(new Error('cancelled')); + const rejected = expect(started).rejects.toBe(cancelled); + controller.abort(cancelled); await jest.advanceTimersByTimeAsync(250); await rejected; expect(stopAsync).toHaveBeenCalledTimes(1); + expect(logger.warn).toHaveBeenCalledWith( + { err: stopError }, + 'Could not stop the reverse tunnel server after it failed to start.' + ); }); }); diff --git a/packages/build-tools/src/steps/utils/__tests__/processOutput.test.ts b/packages/build-tools/src/steps/utils/__tests__/processOutput.test.ts new file mode 100644 index 0000000000..428f5cb005 --- /dev/null +++ b/packages/build-tools/src/steps/utils/__tests__/processOutput.test.ts @@ -0,0 +1,139 @@ +import { type bunyan } from '@expo/logger'; + +import { createProcessOutput } from '../processOutput'; + +const logger = { info: jest.fn() } as unknown as bunyan; + +beforeEach(() => jest.clearAllMocks()); + +it('redacts split credentials before publishing complete lines', () => { + const output = createProcessOutput(logger, ['turn secret']); + output.stdout.append('https://preview.test/?tok'); + output.stdout.append('en=preview-secret&ok=true\n'); + output.stderr.append('Authorization: Bea'); + output.stderr.append('rer tool-secret\n{"credential":"turn secret"}\n'); + expect(logger.info).toHaveBeenNthCalledWith( + 1, + { source: 'stdout' }, + 'https://preview.test/?token=[REDACTED]&ok=true' + ); + expect(logger.info).toHaveBeenNthCalledWith( + 2, + { source: 'stderr' }, + 'Authorization: Bearer [REDACTED]' + ); + expect(output.getOutput()).not.toMatch(/preview-secret|tool-secret|turn secret/); +}); + +it.each([ + [ + 'argent link argent://startup-secret@127.0.0.1:5678', + 'argent link argent://[REDACTED]@127.0.0.1:5678', + ], + [ + 'argent link argent://encoded%2Fsecret@127.0.0.1:5678', + 'argent link argent://[REDACTED]@127.0.0.1:5678', + ], + [ + 'argent link --host 127.0.0.1 --port 5678 --token startup-secret', + 'argent link --host 127.0.0.1 --port 5678 --token [REDACTED]', + ], + ['(or: argent link --token startup-secret)', '(or: argent link --token [REDACTED])'], + [ + 'argent link --token "quoted \\"secret\\"" --port 5678', + 'argent link --token [REDACTED] --port 5678', + ], + ["argent link --token='quoted secret' --port 5678", 'argent link --token=[REDACTED] --port 5678'], +])('redacts startup credentials at every chunk boundary: %s', (line, expected) => { + for (let split = 0; split <= line.length; split++) { + jest.mocked(logger.info).mockClear(); + const output = createProcessOutput(logger); + output.stdout.append(line.slice(0, split)); + expect(logger.info).not.toHaveBeenCalled(); + output.stdout.append(line.slice(split) + '\n'); + expect(logger.info).toHaveBeenCalledWith({ source: 'stdout' }, expected); + expect(output.getOutput()).toBe(expected + '\n'); + } +}); + +it('keeps stdout and stderr fragments separate and decodes split UTF-8', () => { + const output = createProcessOutput(logger); + const bytes = Buffer.from('hello 🌍\n'); + output.stdout.append(bytes.subarray(0, 8)); + output.stderr.append('error\n'); + output.stdout.append(bytes.subarray(8)); + expect(logger.info).toHaveBeenNthCalledWith(1, { source: 'stderr' }, 'error'); + expect(logger.info).toHaveBeenNthCalledWith(2, { source: 'stdout' }, 'hello 🌍'); +}); + +it('omits overlong lines completely and keeps logging the following diagnostics', () => { + const output = createProcessOutput(logger); + output.stdout.append('https://preview.test/?token='); + output.stdout.append('secret'.repeat(20_000)); + expect(logger.info).not.toHaveBeenCalled(); + output.stdout.append('\nfatal diagnostic\n'); + expect(logger.info).toHaveBeenNthCalledWith( + 1, + { source: 'stdout' }, + '[Overlong output line omitted.]' + ); + expect(logger.info).toHaveBeenNthCalledWith(2, { source: 'stdout' }, 'fatal diagnostic'); + expect(output.getOutput()).not.toContain('secret'); +}); + +it('splits multi-line and CRLF chunks and keeps a line exactly at the length limit', () => { + const output = createProcessOutput(logger); + const limit = 16 * 1024; + output.stdout.append('first\r\nsecond\nthi'); + output.stdout.append('rd\n' + 'x'.repeat(limit - 1)); + output.stdout.append('x\n' + 'y'.repeat(limit) + 'y\nafter'); + output.finish(); + expect(jest.mocked(logger.info).mock.calls.map(([, line]) => line)).toEqual([ + 'first', + 'second', + 'third', + 'x'.repeat(limit), + '[Overlong output line omitted.]', + 'after', + ]); +}); + +it('keeps unfinished stdout and stderr lines apart in diagnostics', () => { + const output = createProcessOutput(logger); + output.stdout.append('done\nDownloading 45%'); + output.stderr.append('fatal: port in use'); + expect(output.getOutput()).toBe('done\nDownloading 45%\nfatal: port in use'); + output.stdout.append('\n'); + expect(output.getOutput()).toBe('done\nDownloading 45%\nfatal: port in use'); +}); + +it('redacts final partial lines and bounds diagnostics without capping live output', () => { + const output = createProcessOutput(logger); + for (let index = 0; index < 100; index++) { + output.stdout.append('x'.repeat(1023) + '\n'); + } + output.stderr.append('token=final-secret'); + output.finish(); + expect(logger.info).toHaveBeenCalledTimes(101); + expect(logger.info).toHaveBeenLastCalledWith({ source: 'stderr' }, 'token=[REDACTED]'); + expect(output.getOutput()).toHaveLength(64 * 1024); + expect(output.getOutput()).toContain('token=[REDACTED]'); +}); + +it('applies newly learned secrets to pending output and retained diagnostics', () => { + const secrets: string[] = []; + const output = createProcessOutput(undefined, secrets); + output.stdout.append('opaque-secret\n'); + output.stderr.append('opaque-secret'); + secrets.push('opaque-secret'); + expect(output.getOutput()).not.toContain('opaque-secret'); +}); + +it('redacts JSON token fields with escaped quotes before the token is known', () => { + const output = createProcessOutput(logger); + output.stdout.append(JSON.stringify({ authToken: 'a"b', controlToken: 'android-secret' }) + '\n'); + expect(logger.info).toHaveBeenCalledWith( + { source: 'stdout' }, + '{"authToken":"[REDACTED]","controlToken":"[REDACTED]"}' + ); +}); diff --git a/packages/build-tools/src/steps/utils/__tests__/processOutputProcess.test.ts b/packages/build-tools/src/steps/utils/__tests__/processOutputProcess.test.ts new file mode 100644 index 0000000000..77b1fa4dcd --- /dev/null +++ b/packages/build-tools/src/steps/utils/__tests__/processOutputProcess.test.ts @@ -0,0 +1,156 @@ +import { type bunyan } from '@expo/logger'; +import { setTimeout as delay } from 'node:timers/promises'; + +import { spawnDetached } from '../remoteDeviceRunSession'; + +jest.unmock('node:fs'); +jest.unmock('node:fs/promises'); +jest.mock('../../../sentry'); + +it.each([0, 1])( + 'streams redacted stdout/stderr and drains final partial output on exit %s', + async exitCode => { + const logger = { info: jest.fn() } as unknown as bunyan; + const handle = spawnDetached({ + command: process.execPath, + args: [ + '-e', + ` + console.log('stdout-marker'); + console.error('https://preview.test/?token=startup-secret'); + process.stdout.write('argent link argent://startup-'); + setTimeout(() => { + console.log('secret@127.0.0.1:5678'); + console.log('argent link --host 127.0.0.1 --port 5678 --token startup-secret'); + }, 25); + setTimeout(() => { + process.stderr.write('final diagnostic'); + process.exit(${exitCode}); + }, 100); + `, + ], + env: {}, + logger, + }); + try { + for (let tries = 0; tries < 100 && !handle.getExitError(); tries++) { + await delay(20); + } + await handle.stopAsync(); + expect(handle.getExitError()?.message).toContain(`code ${exitCode}`); + expect(logger.info).toHaveBeenCalledWith({ source: 'stdout' }, 'stdout-marker'); + expect(logger.info).toHaveBeenCalledWith( + { source: 'stderr' }, + 'https://preview.test/?token=[REDACTED]' + ); + expect(logger.info).toHaveBeenCalledWith({ source: 'stderr' }, 'final diagnostic'); + expect(logger.info).toHaveBeenCalledWith( + { source: 'stdout' }, + 'argent link argent://[REDACTED]@127.0.0.1:5678' + ); + expect(logger.info).toHaveBeenCalledWith( + { source: 'stdout' }, + 'argent link --host 127.0.0.1 --port 5678 --token [REDACTED]' + ); + expect(JSON.stringify(jest.mocked(logger.info).mock.calls)).not.toContain('startup-secret'); + expect(handle.getOutput()).not.toContain('startup-secret'); + } finally { + await handle.stopAsync(); + } + } +); + +it('drains descendant shutdown logs after the launcher has exited', async () => { + const logger = { info: jest.fn() } as unknown as bunyan; + const childScript = ` + process.on('SIGTERM', () => setTimeout(() => { + console.error('descendant-shutdown-marker'); process.exit(0); + }, 150)); + console.log('descendant-ready'); setInterval(() => {}, 1000); + `; + const handle = spawnDetached({ + command: process.execPath, + args: [ + '-e', + ` + require('node:child_process').spawn(process.execPath, ['-e', ${JSON.stringify(childScript)}], { stdio: 'inherit' }); + setTimeout(() => process.exit(0), 200); + `, + ], + env: {}, + logger, + }); + try { + for (let tries = 0; tries < 100 && !handle.getExitError(); tries++) { + await delay(20); + } + expect(handle.getExitError()).toBeDefined(); + await handle.stopAsync(); + expect(logger.info).toHaveBeenCalledWith({ source: 'stderr' }, 'descendant-shutdown-marker'); + } finally { + await handle.stopAsync(); + } +}, 20_000); + +it('fails a stop whose output a detached descendant still holds open, after flushing it', async () => { + const logger = { info: jest.fn() } as unknown as bunyan; + const lines = (source: string) => + jest + .mocked(logger.info) + .mock.calls.filter(([fields]) => (fields as { source: string }).source === source) + .map(([, line]) => line as unknown as string); + // The descendant leaves the process group and keeps the inherited pipes until killed. + const escapedScript = ` + process.stderr.on('error', () => {}); + setInterval(() => console.error('escaped-tick'), 50); + setTimeout(() => process.exit(0), 30_000); + `; + const handle = spawnDetached({ + command: process.execPath, + args: [ + '-e', + ` + const escaped = require('node:child_process').spawn( + process.execPath, + ['-e', ${JSON.stringify(escapedScript)}], + { stdio: 'inherit', detached: true } + ); + console.error('escaped-pid ' + escaped.pid); + process.stdout.write('launcher partial'); + setInterval(() => {}, 1000); + `, + ], + env: {}, + logger, + }); + let escapedPid: number | undefined; + try { + for (let tries = 0; tries < 100; tries++) { + const pidLine = lines('stderr').find(line => line.startsWith('escaped-pid ')); + escapedPid = pidLine ? Number(pidLine.split(' ')[1]) : undefined; + if (escapedPid !== undefined && lines('stderr').includes('escaped-tick')) { + break; + } + await delay(20); + } + expect(escapedPid).toBeDefined(); + expect(lines('stdout')).toEqual([]); + + await expect(handle.stopAsync()).rejects.toThrow( + 'Process output drain timed out after 5000ms.' + ); + expect(handle.getExitError()?.message).toBe('Process exited with signal SIGTERM.'); + expect(lines('stdout')).toEqual(['launcher partial']); + expect(handle.getOutput()).toContain('launcher partial'); + const ticks = lines('stderr').length; + await delay(250); + expect(lines('stderr')).toHaveLength(ticks); + } finally { + if (escapedPid !== undefined) { + try { + process.kill(escapedPid, 'SIGKILL'); + } catch {} + } + await handle.stopAsync().catch(() => {}); + } +}, 20_000); diff --git a/packages/build-tools/src/steps/utils/__tests__/remoteDeviceRunSession.test.ts b/packages/build-tools/src/steps/utils/__tests__/remoteDeviceRunSession.test.ts index 2348c41f9c..4c81dcc763 100644 --- a/packages/build-tools/src/steps/utils/__tests__/remoteDeviceRunSession.test.ts +++ b/packages/build-tools/src/steps/utils/__tests__/remoteDeviceRunSession.test.ts @@ -71,6 +71,7 @@ function createLoggerMock(): bunyan { warn: jest.fn(), error: jest.fn(), debug: jest.fn(), + child: jest.fn().mockReturnThis(), } as unknown as bunyan; } @@ -677,6 +678,43 @@ describe(waitForWebPreviewReadyAsync, () => { }); describe(startNgrokTunnelAsync, () => { + it.each(['rejected', 'stalled'] as const)( + 'retains a %s close failure on repeated stops', + async mode => { + jest.useFakeTimers(); + try { + const failure = new Error('close failed'); + const close = jest + .fn() + .mockImplementation(() => + mode === 'rejected' ? Promise.reject(failure) : new Promise(() => {}) + ); + jest.mocked(ngrok.forward).mockResolvedValue({ + url: () => 'https://web-preview.example.test', + close, + } as never); + const tunnel = await startNgrokTunnelAsync({ + port: 4321, + subdomainPrefix: 'web-preview', + baseDomain: 'eas-simulator.ngrok.dev', + authtoken: 'token', + logger: createLoggerMock(), + }); + const stopping = tunnel.stopAsync(); + const assertion = expect(stopping).rejects.toThrow( + mode === 'rejected' ? 'close failed' : 'Ngrok tunnel stop timed out after 4000ms.' + ); + expect(tunnel.stopAsync()).toBe(stopping); + await jest.advanceTimersByTimeAsync(4_000); + await assertion; + await expect(tunnel.stopAsync()).rejects.toThrow(); + expect(close).toHaveBeenCalledTimes(1); + } finally { + jest.useRealTimers(); + } + } + ); + it('uses a 128-bit capability hostname and exposes explicit cleanup', async () => { const close = jest.fn().mockResolvedValue(undefined); jest.mocked(ngrok.forward).mockResolvedValue({ @@ -716,7 +754,15 @@ describe('spawnDetached process group shutdown', () => { beforeEach(() => { const spawned = Object.assign(Promise.resolve(undefined), { - child: { pid: 4321, unref: jest.fn(), once: jest.fn() }, + child: { + pid: 4321, + unref: jest.fn(), + once: jest.fn((event, callback) => { + if (event === 'close') { + queueMicrotask(callback); + } + }), + }, }); jest.mocked(spawn).mockReturnValue(spawned as never); }); @@ -751,7 +797,16 @@ describe('spawnDetached process group shutdown', () => { }); it('kills a detached child that outlives the shutdown deadline', async () => { - const kill = jest.spyOn(process, 'kill').mockReturnValue(true); + let killed = false; + const kill = jest.spyOn(process, 'kill').mockImplementation((pid, signal) => { + if (pid === -4321 && signal === 'SIGKILL') { + killed = true; + } + if (killed && signal === 0) { + throw Object.assign(new Error('Process group exited'), { code: 'ESRCH' }); + } + return true; + }); const detached = spawnDetached({ command: 'npx', args: [], env, stopGracePeriodMs: 0 }); await detached.stopAsync(); @@ -790,7 +845,11 @@ describe(startDeviceSessionHostAsync, () => { child: { pid: undefined, unref: jest.fn(), - once: jest.fn(), + once: jest.fn((event, callback) => { + if (event === 'close') { + queueMicrotask(callback); + } + }), }, }); jest.mocked(spawn).mockReturnValue(spawnPromise as never); diff --git a/packages/build-tools/src/steps/utils/__tests__/serveSimLogsRecorder.test.ts b/packages/build-tools/src/steps/utils/__tests__/serveSimLogsRecorder.test.ts index ad2a54e6db..757322184e 100644 --- a/packages/build-tools/src/steps/utils/__tests__/serveSimLogsRecorder.test.ts +++ b/packages/build-tools/src/steps/utils/__tests__/serveSimLogsRecorder.test.ts @@ -98,13 +98,22 @@ it.each([undefined, 'all'])('refuses an unconfirmed user-app scope (%s)', async it('aborts a quiet live stream and drains preceding writes before returning', async () => { const controller = new AbortController(); + const fsPromises = jest.requireActual('node:fs/promises'); + const openFile = fsPromises.open; + jest.spyOn(fsPromises, 'open').mockImplementationOnce(async (...args) => { + const file = await openFile(...args); + const write = file.writeFile.bind(file); + jest.spyOn(file, 'writeFile').mockImplementationOnce(async (...args) => { + const pending = write(...args); + controller.abort(); + await pending; + }); + return file; + }); const stream = new Readable({ read() {} }); stream.push('data: {"pid":42}\n\n'); jest.mocked(fetch).mockResolvedValue(new Response(stream)); - const done = record({ signal: controller.signal }); - await delay(20); - controller.abort(); - expect((await done).receivedData).toBe(true); + expect((await record({ signal: controller.signal })).receivedData).toBe(true); expect(stream.destroyed).toBe(true); expect(await readFile(path.join(directory, 'logs.ndjson'), 'utf8')).toBe('{"pid":42}\n'); }); diff --git a/packages/build-tools/src/steps/utils/deviceSessionHost.ts b/packages/build-tools/src/steps/utils/deviceSessionHost.ts index 2ddf19d877..145a89c6a2 100644 --- a/packages/build-tools/src/steps/utils/deviceSessionHost.ts +++ b/packages/build-tools/src/steps/utils/deviceSessionHost.ts @@ -355,6 +355,11 @@ export async function startDeviceSessionHostAsync( logger.info( `Launching ${packageSpec} on ${WEB_PREVIEW_HOST}:${port} via ${previewExec.command}.` ); + // Redact these credentials before forwarding process output to build logs. + const secrets = [ + ...turnArgs.filter((_, index) => turnArgs[index - 1] === '--turn-credential'), + ...(recording ? [recording.controlToken] : []), + ]; const screenshots = await startDeviceRunSessionScreenshotsAsync(ctx, { deviceRunSessionId: getDeviceRunSessionIdOrThrow(env), logger, @@ -373,6 +378,8 @@ export async function startDeviceSessionHostAsync( stopGracePeriodMs: recording ? RECORDING_STOP_GRACE_PERIOD_MS : SERVE_SIM_STOP_GRACE_PERIOD_MS, + logger, + secrets, }); } catch (error) { // Nothing was spawned, so nothing can still write into the directory. @@ -472,6 +479,7 @@ export async function startDeviceSessionHostAsync( 'report it if it repeats.' ); } + secrets.push(previewToken); IosSimulatorRecordingUtils.useServeSimPackage(packageSpec); } // Android installed FFmpeg before launching the host. The optional thumbnail must not delay diff --git a/packages/build-tools/src/steps/utils/localEgress.ts b/packages/build-tools/src/steps/utils/localEgress.ts index af9460140c..c08f10dc2f 100644 --- a/packages/build-tools/src/steps/utils/localEgress.ts +++ b/packages/build-tools/src/steps/utils/localEgress.ts @@ -191,12 +191,14 @@ export async function startChiselServerAsync({ controlPort, authfilePath, env, + logger, signal, }: { chiselPath: string; controlPort: number; authfilePath: string; env: BuildStepEnv; + logger: bunyan; signal?: AbortSignal; }): Promise<{ process: DetachedProcessHandle; fingerprint: string }> { const server = spawnDetached({ @@ -244,7 +246,11 @@ export async function startChiselServerAsync({ }` ); } catch (error) { - await server.stopAsync(); + await server + .stopAsync() + .catch(err => + logger.warn({ err }, 'Could not stop the reverse tunnel server after it failed to start.') + ); throw error; } } diff --git a/packages/build-tools/src/steps/utils/processOutput.ts b/packages/build-tools/src/steps/utils/processOutput.ts new file mode 100644 index 0000000000..71c6b790c5 --- /dev/null +++ b/packages/build-tools/src/steps/utils/processOutput.ts @@ -0,0 +1,88 @@ +import { type bunyan } from '@expo/logger'; +import { StringDecoder } from 'node:string_decoder'; +import { stripVTControlCharacters } from 'node:util'; + +const MAX_LINE_CHARS = 16 * 1024; +const MAX_OUTPUT_CHARS = 64 * 1024; + +export function createProcessOutput(logger?: bunyan, secrets: string[] = []) { + const redact = (text: string): string => { + text = stripVTControlCharacters(text); + for (const secret of secrets.filter(Boolean)) { + for (const value of [ + secret, + encodeURIComponent(secret), + JSON.stringify(secret).slice(1, -1), + ]) { + text = text.replaceAll(value, '[REDACTED]'); + } + } + return text + .replace(/([?&]token=)[^\s&#"'<>]+/gi, '$1[REDACTED]') + .replace(/(argent:\/\/)[^\s/@]+@/gi, '$1[REDACTED]@') + .replace( + /("(?:[a-z_]*token|credential|password)"\s*:\s*")(?:\\.|[^"\\\r\n])*(")/gi, + '$1[REDACTED]$2' + ) + .replace(/(Bearer\s+)[^\s"'<>]+/gi, '$1[REDACTED]') + .replace( + /((?:--)?(?:token|credential|password)[=:]\s*|--(?:token|credential|password)\s+)(?:"(?:\\.|[^"\\\r\n])*"|'(?:\\.|[^'\\\r\n])*'|[^\s,&#"'<>()]+)/gi, + '$1[REDACTED]' + ); + }; + let output = ''; + const streams = (['stdout', 'stderr'] as const).map(source => { + const decoder = new StringDecoder('utf8'); + let pending = ''; + let omitted = false; + const publish = (): void => { + const line = omitted ? '[Overlong output line omitted.]' : redact(pending); + output = (output + line + '\n').slice(-MAX_OUTPUT_CHARS); + logger?.info({ source }, line); + pending = ''; + omitted = false; + }; + const appendText = (text: string): void => { + const parts = text.split('\n'); + for (const [index, part] of parts.entries()) { + if (!omitted) { + if (pending.length + part.length > MAX_LINE_CHARS) { + pending = ''; + omitted = true; + } else { + pending += part; + } + } + if (index < parts.length - 1) { + pending = pending.replace(/\r$/, ''); + publish(); + } + } + }; + return { + append(chunk: Buffer | string): void { + appendText(decoder.write(Buffer.isBuffer(chunk) ? chunk : Buffer.from(chunk))); + }, + finish(): void { + appendText(decoder.end()); + if (pending || omitted) { + publish(); + } + }, + getPending: () => (omitted ? '[Overlong output line omitted.]' : redact(pending)), + }; + }); + return { + stdout: streams[0], + stderr: streams[1], + finish: () => streams.forEach(stream => stream.finish()), + getOutput: () => + ( + redact(output) + + streams + .map(stream => stream.getPending()) + .filter(Boolean) + .join('\n') + ).slice(-MAX_OUTPUT_CHARS), + }; +} diff --git a/packages/build-tools/src/steps/utils/remoteDeviceRunSession.ts b/packages/build-tools/src/steps/utils/remoteDeviceRunSession.ts index 3d8ca1fece..ee7e97129c 100644 --- a/packages/build-tools/src/steps/utils/remoteDeviceRunSession.ts +++ b/packages/build-tools/src/steps/utils/remoteDeviceRunSession.ts @@ -30,6 +30,8 @@ import { Sentry } from '../../sentry'; import { isProcessGroupRunning } from '../../utils/processes'; import { sleepAsync } from '../../utils/retry'; import { turtleFetch } from '../../utils/turtleFetch'; +import { createProcessOutput } from './processOutput'; +import { withDeviceRunSessionTimeoutAsync } from './deviceRunSessionTimeout'; const XCODE_DEVELOPER_DIR = '/Applications/Xcode.app/Contents/Developer'; @@ -647,24 +649,34 @@ export function spawnDetached({ cwd, env, stopGracePeriodMs, + logger, + secrets, }: { command: string; args: string[]; cwd?: string; env: BuildStepEnv; stopGracePeriodMs?: number; + logger?: bunyan; + secrets?: string[]; }): DetachedProcessHandle { const promise = spawn(command, args, { cwd, env, stdio: ['ignore', 'pipe', 'pipe'], detached: true, + ignoreStdio: true, }); + const output = createProcessOutput(logger, secrets); + const outputDrained = new Promise(resolve => + promise.child.once('close', () => { + output.finish(); + resolve(); + }) + ); // Observe completion without rejecting in the background. Startup callers can // distinguish a dead process from one that is still preparing its state file. let exitError: Error | undefined; - // The spawn promise waits for stdio to close. Descendants may keep those - // pipes open after the launcher exits, so observe the exit itself as well. promise.child.once('exit', (code, signal) => { exitError = new Error( signal ? `Process exited with signal ${signal}.` : `Process exited with code ${code}.` @@ -680,19 +692,28 @@ export function spawnDetached({ ); promise.child.unref(); - let output = ''; - const appendChunk = (chunk: Buffer | string): void => { - output += chunk.toString(); - }; - promise.child.stdout?.on('data', appendChunk); - promise.child.stderr?.on('data', appendChunk); + promise.child.stdout?.on('data', chunk => output.stdout.append(chunk)); + promise.child.stderr?.on('data', chunk => output.stderr.append(chunk)); const pid = promise.child.pid; return { pid, - getOutput: () => output, + getOutput: output.getOutput, getExitError: () => exitError, - stopAsync: async () => await stopDetachedProcessAsync(pid, stopGracePeriodMs), + stopAsync: async () => { + await stopDetachedProcessAsync(pid, stopGracePeriodMs); + try { + await withDeviceRunSessionTimeoutAsync( + { name: 'Process output drain', timeoutMs: 5_000 }, + async () => await outputDrained + ); + } catch (err) { + promise.child.stdout?.destroy(); + promise.child.stderr?.destroy(); + output.finish(); + throw err; + } + }, }; } @@ -826,21 +847,22 @@ export async function startNgrokTunnelAsync({ await listener.close(); throw new SystemError(`ngrok tunnel for ${domain} did not return a public URL.`); } - let stopped = false; + let stopTask: Promise | undefined; return { url, subdomainId, - stopAsync: async () => { - if (stopped) { - return; - } - stopped = true; - try { - await listener.close(); - } catch (error) { - logger.warn({ err: error }, `Could not stop ngrok tunnel ${domain}.`); - } - }, + stopAsync: () => + (stopTask ??= (async () => { + try { + await withDeviceRunSessionTimeoutAsync( + { name: 'Ngrok tunnel stop', timeoutMs: 4_000 }, + async () => await listener.close() + ); + } catch (error) { + logger.warn({ err: error }, `Could not stop ngrok tunnel ${domain}.`); + throw error; + } + })()), }; }