diff --git a/.changeset/simulator-get-job-run-errors.md b/.changeset/simulator-get-job-run-errors.md new file mode 100644 index 0000000000..169c4ebd2b --- /dev/null +++ b/.changeset/simulator-get-job-run-errors.md @@ -0,0 +1,5 @@ +--- +'eas-cli': patch +--- + +Show why a simulator session failed in `eas simulator:get`, and add an `errors` array to its `--json` output. For an unknown error, `simulator:start` and `simulator:get` now show the failed step's error from the session logs. diff --git a/packages/eas-cli/src/commands/simulator/__tests__/get.test.ts b/packages/eas-cli/src/commands/simulator/__tests__/get.test.ts index d8dca493f7..47f9dbf03f 100644 --- a/packages/eas-cli/src/commands/simulator/__tests__/get.test.ts +++ b/packages/eas-cli/src/commands/simulator/__tests__/get.test.ts @@ -40,6 +40,7 @@ jest.mock('../../../utils/json'); type DeviceRunSessionById = DeviceRunSessionByIdQuery['deviceRunSessions']['byId']; const mockByIdAsync = jest.mocked(DeviceRunSessionQuery.byIdAsync); +const mockJobRunErrorsByIdAsync = jest.mocked(DeviceRunSessionQuery.jobRunErrorsByIdAsync); const mockEnableJsonOutput = jest.mocked(enableJsonOutput); const mockLoadSimulatorEnvironmentVariablesAsync = jest.mocked(loadSimulatorEnvAsync); const mockPrintJsonOnlyOutput = jest.mocked(printJsonOnlyOutput); @@ -108,6 +109,7 @@ describe(SimulatorGet, () => { beforeEach(() => { jest.clearAllMocks(); mockLoadSimulatorEnvironmentVariablesAsync.mockResolvedValue(); + mockJobRunErrorsByIdAsync.mockResolvedValue(null); }); function createCommand(argv: string[]): { @@ -162,6 +164,79 @@ describe(SimulatorGet, () => { previewApiUrl: null, }, artifacts: session.artifacts, + errors: [], + }); + expect(mockJobRunErrorsByIdAsync).not.toHaveBeenCalled(); + }); + + describe('errored sessions', () => { + const jobRunErrors = { + id: 'job-123', + errors: [ + { + errorCode: 'EAS_IOS_SIMULATOR_NOT_FOUND', + message: 'No available iOS Simulator is named "iPhone 16 Pro".', + docsUrl: null, + }, + ], + logFileUrls: [], + }; + + it('includes the job run errors in JSON output', async () => { + mockByIdAsync.mockResolvedValue( + makeDeviceRunSession({ status: DeviceRunSessionStatus.Errored, remoteConfig: null }) + ); + mockJobRunErrorsByIdAsync.mockResolvedValue(jobRunErrors); + + const { command } = createCommand(['--id', 'session-123', '--json']); + await command.runAsync(); + + expect(mockJobRunErrorsByIdAsync).toHaveBeenCalledWith(graphqlClient, 'session-123', { + signal: expect.any(AbortSignal), + }); + expect(mockPrintJsonOnlyOutput).toHaveBeenCalledWith( + expect.objectContaining({ + errors: [ + { + errorCode: 'EAS_IOS_SIMULATOR_NOT_FOUND', + message: 'No available iOS Simulator is named "iPhone 16 Pro".', + docsUrl: null, + }, + ], + }) + ); + }); + + it('prints the job run errors when only the job run errored', async () => { + mockByIdAsync.mockResolvedValue( + makeDeviceRunSession({ + status: DeviceRunSessionStatus.Stopped, + remoteConfig: null, + turtleJobRun: { id: 'job-123', status: JobRunStatus.Errored }, + }) + ); + mockJobRunErrorsByIdAsync.mockResolvedValue(jobRunErrors); + + const { command } = createCommand(['--id', 'session-123']); + await command.runAsync(); + + expect(Log.gray).toHaveBeenCalledWith('Session errors:'); + expect(Log.error).toHaveBeenCalledWith( + ' No available iOS Simulator is named "iPhone 16 Pro".' + ); + }); + + it('prints no errors section when the job run errors cannot be fetched', async () => { + mockByIdAsync.mockResolvedValue( + makeDeviceRunSession({ status: DeviceRunSessionStatus.Errored, remoteConfig: null }) + ); + mockJobRunErrorsByIdAsync.mockRejectedValue(new Error('graphql boom')); + + const { command } = createCommand(['--id', 'session-123']); + await command.runAsync(); + + expect(Log.gray).not.toHaveBeenCalledWith('Session errors:'); + expect(Log.error).not.toHaveBeenCalled(); }); }); diff --git a/packages/eas-cli/src/commands/simulator/__tests__/index.test.ts b/packages/eas-cli/src/commands/simulator/__tests__/index.test.ts index 9aad7d80fe..592d1ee6f0 100644 --- a/packages/eas-cli/src/commands/simulator/__tests__/index.test.ts +++ b/packages/eas-cli/src/commands/simulator/__tests__/index.test.ts @@ -6,6 +6,7 @@ import { GraphQLError } from 'graphql'; import { SimulatorEvent, isAnalyticsOptedOutAsync } from '../../../analytics/AnalyticsManager'; import { getAgentTelemetryContext } from '../../../analytics/agent'; import { ExpoGraphqlClient } from '../../../commandUtils/context/contextUtils/createGraphqlClient'; +import fetch from '../../../fetch'; import { AppPlatform, CreateDeviceRunSessionMutation, @@ -44,6 +45,7 @@ jest.mock('../../../analytics/AnalyticsManager', () => ({ jest.mock('../../../analytics/agent'); jest.mock('../../../graphql/mutations/DeviceRunSessionMutation'); jest.mock('../../../graphql/queries/DeviceRunSessionAvailabilityQuery'); +jest.mock('../../../fetch'); jest.mock('../../../graphql/queries/DeviceRunSessionQuery'); jest.mock('../../../log', () => ({ __esModule: true, @@ -107,6 +109,7 @@ const mockEnsureDeviceRunSessionStoppedAsync = jest.mocked( const mockAvailabilityByAppIdAsync = jest.mocked(DeviceRunSessionAvailabilityQuery.byAppIdAsync); const mockByIdAsync = jest.mocked(DeviceRunSessionQuery.byIdAsync); const mockJobRunErrorsByIdAsync = jest.mocked(DeviceRunSessionQuery.jobRunErrorsByIdAsync); +const mockFetch = jest.mocked(fetch); const mockLoadSimulatorEnvAsync = jest.mocked(loadSimulatorEnvAsync); const mockLogEvent = jest.fn(); const mockFlushAsync = jest.fn(async () => {}); @@ -1996,6 +1999,51 @@ describe(Simulator, () => { describe('job run errors', () => { const erroredSessionMessage = 'Simulator session session-123 errored before the agent-device session was ready. https://expo.dev/accounts/testuser/projects/testapp/simulator-sessions/session-123'; + const logFileUrl = 'https://logs.example.com/job-123'; + const unknownError = { + errorCode: 'UNKNOWN_ERROR', + message: 'Unknown error. See logs for more information.', + docsUrl: null, + }; + + // Shaped like the worker's bunyan output: the failing call logs at error level with `err`, + // then the step runner logs an end-step marker with result "fail". + function failedStepLogLines( + stepId: string, + displayName: string, + messages: string[] + ): Record[] { + return [ + { + level: 30, + buildStepId: stepId, + buildStepDisplayName: displayName, + marker: 'start-step', + msg: `Executing build step "${displayName}"`, + }, + ...messages.map(msg => ({ + level: 50, + buildStepId: stepId, + buildStepDisplayName: displayName, + msg, + err: { message: msg }, + })), + { + level: 50, + buildStepId: stepId, + buildStepDisplayName: displayName, + marker: 'end-step', + result: 'fail', + msg: `Build step "${displayName}" failed`, + }, + ]; + } + + function mockLogFile(logLines: Record[]): void { + mockFetch.mockResolvedValue({ + text: async () => logLines.map(line => JSON.stringify(line)).join('\n'), + } as unknown as Awaited>); + } beforeEach(() => { mockByIdAsync.mockResolvedValue( @@ -2003,14 +2051,19 @@ describe(Simulator, () => { ); }); - it('keeps the message unchanged when the job run has no errors', async () => { - mockJobRunErrorsByIdAsync.mockResolvedValue({ id: 'job-123', errors: [] }); + it('keeps the message unchanged without reading logs when the job run has no errors', async () => { + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [], + logFileUrls: [logFileUrl], + }); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); await expect(command.runAsync()).rejects.toThrow( expect.objectContaining({ message: erroredSessionMessage }) ); + expect(mockFetch).not.toHaveBeenCalled(); }); it('lists each job run error on its own line with its docs link', async () => { @@ -2028,6 +2081,7 @@ describe(Simulator, () => { docsUrl: 'https://docs.expo.dev/simulator', }, ], + logFileUrls: [logFileUrl], }); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); @@ -2037,84 +2091,194 @@ describe(Simulator, () => { message: `${erroredSessionMessage}\nNo available iOS Simulator is named "iPhone 16 Pro".\nThe build cannot be installed on a simulator. Learn more: https://docs.expo.dev/simulator`, }) ); + expect(mockFetch).not.toHaveBeenCalled(); }); - it('prints an unknown error as reported', async () => { + it('reads the failed step error from the job run logs for an unknown error', async () => { mockJobRunErrorsByIdAsync.mockResolvedValue({ id: 'job-123', - errors: [ - { - errorCode: 'UNKNOWN_ERROR', - message: 'Unknown error. See logs for more information.', - docsUrl: null, - }, - ], + errors: [unknownError], + logFileUrls: [logFileUrl], }); + mockLogFile([ + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Install application', + msg: 'Retrying install', + err: { message: 'Retrying install' }, + }, + { + level: 30, + buildStepId: 'step-001', + marker: 'end-step', + result: 'success', + msg: 'Finished', + }, + ...failedStepLogLines('step-002', 'Launch application', [ + 'adb shell am start exited with non-zero code: 1', + ]), + { + level: 20, + buildStepId: 'step-002', + msg: 'Getting value for output parameter "x" failed.', + err: { message: 'not set' }, + }, + { + level: 40, + msg: 'Could not stop the emulator during remote session teardown.', + err: { message: 'teardown' }, + }, + ]); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); await expect(command.runAsync()).rejects.toThrow( expect.objectContaining({ - message: `${erroredSessionMessage}\nUnknown error. See logs for more information.`, + message: `${erroredSessionMessage}\nLaunch application: adb shell am start exited with non-zero code: 1`, }) ); + expect(mockFetch).toHaveBeenCalledWith( + logFileUrl, + expect.objectContaining({ size: 20 * 1024 * 1024, signal: expect.any(AbortSignal) }) + ); }); - it('keeps the message unchanged when the job run errors cannot be fetched', async () => { - mockJobRunErrorsByIdAsync.mockRejectedValue(new Error('graphql boom')); + it('prints the masked log message instead of the unmasked err.message', async () => { + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [unknownError], + logFileUrls: [logFileUrl], + }); + mockLogFile([ + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Run script', + msg: 'curl -H "Authorization: ********" exited with non-zero code: 22', + err: { message: 'curl -H "Authorization: secret-token" exited with non-zero code: 22' }, + }, + { + level: 50, + buildStepId: 'step-001', + marker: 'end-step', + result: 'fail', + msg: 'Build step "Run script" failed', + }, + ]); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); await expect(command.runAsync()).rejects.toThrow( - expect.objectContaining({ message: erroredSessionMessage }) + expect.objectContaining({ + message: `${erroredSessionMessage}\nRun script: curl -H "Authorization: ********" exited with non-zero code: 22`, + }) ); - expect(mockEnsureDeviceRunSessionStoppedAsync).toHaveBeenCalled(); }); - it('looks up the job run errors with an abortable signal', async () => { - mockJobRunErrorsByIdAsync.mockResolvedValue({ id: 'job-123', errors: [] }); + it('shows the first failed step, then only the error line of later failed steps', async () => { + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [unknownError], + logFileUrls: [logFileUrl], + }); + mockLogFile([ + ...failedStepLogLines('step-001', 'Boot', ['A', 'B']), + ...failedStepLogLines('step-002', 'Finish recordings', ['C', 'D']), + ]); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); - await expect(command.runAsync()).rejects.toThrow(); - expect(mockJobRunErrorsByIdAsync).toHaveBeenCalledWith(expect.anything(), 'session-123', { - signal: expect.any(AbortSignal), - }); + await expect(command.runAsync()).rejects.toThrow( + expect.objectContaining({ + message: `${erroredSessionMessage}\nBoot: B\nFinish recordings: D`, + }) + ); }); - it('gives up on a job run error lookup that does not settle and still stops the session', async () => { - jest.spyOn(AbortSignal, 'timeout').mockReturnValue(AbortSignal.abort(new Error('timed out'))); - mockJobRunErrorsByIdAsync.mockImplementation( - async (_client, _id, { signal }) => - await new Promise((_resolve, reject) => { - if (signal.aborted) { - reject(signal.reason); - } - signal.addEventListener('abort', () => { - reject(signal.reason); - }); - }) + it('truncates very long log errors', async () => { + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [unknownError], + logFileUrls: [logFileUrl], + }); + mockLogFile(failedStepLogLines('step-001', 'Boot', ['x'.repeat(2000)])); + + const { command } = createCommand(['--platform', 'ios', '--non-interactive']); + + await expect(command.runAsync()).rejects.toThrow( + expect.objectContaining({ + message: `${erroredSessionMessage}\n${`Boot: ${'x'.repeat(2000)}`.slice(0, 500)}…`, + }) ); + }); + + it('keeps the job run error when no step failed, ignoring errors that steps ignored', async () => { + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [ + { + errorCode: 'UNKNOWN_ERROR', + message: + 'Unknown error. See logs of the Complete job build phase for more information.', + docsUrl: null, + }, + ], + logFileUrls: [logFileUrl], + }); + mockLogFile([ + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Upload artifact', + msg: 'Failed to upload screen-recording. Ignoring error.', + err: { message: 'upload failed' }, + }, + { + level: 30, + buildStepId: 'step-001', + marker: 'end-step', + result: 'success', + msg: 'Finished', + }, + { level: 50, phase: 'COMPLETE_JOB', msg: '', err: { message: 'upload outputs failed' } }, + ]); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); await expect(command.runAsync()).rejects.toThrow( - expect.objectContaining({ message: erroredSessionMessage }) + expect.objectContaining({ + message: `${erroredSessionMessage}\nUnknown error. See logs of the Complete job build phase for more information.`, + }) ); - expect(mockEnsureDeviceRunSessionStoppedAsync).toHaveBeenCalled(); }); - it('truncates very long job run errors', async () => { + it('falls back to the unknown error message when the job run logs cannot be read', async () => { mockJobRunErrorsByIdAsync.mockResolvedValue({ id: 'job-123', - errors: [{ errorCode: 'EAS_SIMULATOR_ERROR', message: 'x'.repeat(2000), docsUrl: null }], + errors: [unknownError], + logFileUrls: [logFileUrl], }); + mockFetch.mockRejectedValue(new Error('Request failed: 503 (Service Unavailable)')); + + const { command } = createCommand(['--platform', 'ios', '--non-interactive']); + + await expect(command.runAsync()).rejects.toThrow( + expect.objectContaining({ + message: `${erroredSessionMessage}\nUnknown error. See logs for more information.`, + }) + ); + }); + + it('keeps the message unchanged when the job run errors cannot be fetched', async () => { + mockJobRunErrorsByIdAsync.mockRejectedValue(new Error('graphql boom')); const { command } = createCommand(['--platform', 'ios', '--non-interactive']); await expect(command.runAsync()).rejects.toThrow( - expect.objectContaining({ message: `${erroredSessionMessage}\n${'x'.repeat(500)}…` }) + expect.objectContaining({ message: erroredSessionMessage }) ); + expect(mockEnsureDeviceRunSessionStoppedAsync).toHaveBeenCalled(); }); }); @@ -2430,6 +2594,7 @@ describe(Simulator, () => { docsUrl: null, }, ], + logFileUrls: [], }); const { command } = createCommand(['--platform', 'ios']); diff --git a/packages/eas-cli/src/commands/simulator/get.ts b/packages/eas-cli/src/commands/simulator/get.ts index 8eb4117653..bc5fa743a5 100644 --- a/packages/eas-cli/src/commands/simulator/get.ts +++ b/packages/eas-cli/src/commands/simulator/get.ts @@ -6,7 +6,11 @@ import { EasNonInteractiveAndJsonFlags, resolveNonInteractiveAndJsonFlags, } from '../../commandUtils/flags'; -import { DeviceRunSessionByIdQuery, DeviceRunSessionStatus } from '../../graphql/generated'; +import { + DeviceRunSessionByIdQuery, + DeviceRunSessionStatus, + JobRunStatus, +} from '../../graphql/generated'; import { DeviceRunSessionQuery } from '../../graphql/queries/DeviceRunSessionQuery'; import Log, { link } from '../../log'; import { ora } from '../../ora'; @@ -15,6 +19,11 @@ import { SIMULATOR_DOTENV_FILE_NAME, loadSimulatorEnvAsync, } from '../../simulator/env'; +import { + SimulatorSessionError, + fetchSimulatorSessionErrorsAsync, + formatSimulatorSessionError, +} from '../../simulator/jobRunErrors'; import { deviceRunSessionTypeToFlagValue, formatRemoteSessionInstructions, @@ -87,6 +96,11 @@ export default class SimulatorGet extends EasCommand { session.app.slug, session.id ); + const errors: SimulatorSessionError[] = + session.status === DeviceRunSessionStatus.Errored || + session.turtleJobRun?.status === JobRunStatus.Errored + ? await fetchSimulatorSessionErrorsAsync(graphqlClient, session.id) + : []; if (jsonFlag) { printJsonOnlyOutput({ @@ -109,6 +123,7 @@ export default class SimulatorGet extends EasCommand { ) : session.remoteConfig, artifacts: session.artifacts, + errors, }); return; } @@ -116,6 +131,14 @@ export default class SimulatorGet extends EasCommand { Log.newLine(); Log.log(formatSessionFields(session, deviceRunSessionUrl)); + if (errors.length > 0) { + Log.newLine(); + Log.gray('Session errors:'); + for (const error of errors) { + Log.error(` ${formatSimulatorSessionError(error)}`); + } + } + if (session.status === DeviceRunSessionStatus.InProgress) { Log.newLine(); if (session.remoteConfig) { diff --git a/packages/eas-cli/src/commands/simulator/index.ts b/packages/eas-cli/src/commands/simulator/index.ts index 3d9db93625..7ac3e40fa6 100644 --- a/packages/eas-cli/src/commands/simulator/index.ts +++ b/packages/eas-cli/src/commands/simulator/index.ts @@ -27,7 +27,7 @@ import { import { DeviceRunSessionMutation } from '../../graphql/mutations/DeviceRunSessionMutation'; import { DeviceRunSessionAvailabilityQuery } from '../../graphql/queries/DeviceRunSessionAvailabilityQuery'; import { DeviceRunSessionQuery } from '../../graphql/queries/DeviceRunSessionQuery'; -import Log, { learnMore, link } from '../../log'; +import Log, { link } from '../../log'; import { Ora, ora } from '../../ora'; import { promptAsync } from '../../prompts'; import { parseEgressAllowList, runLocalEgressAsync } from '../../simulator/egress'; @@ -41,6 +41,10 @@ import { writeSimulatorEnvAsync, } from '../../simulator/env'; import { resolveExpoGoSdkVersionAsync } from '../../simulator/expoGo'; +import { + fetchSimulatorSessionErrorsAsync, + formatSimulatorSessionError, +} from '../../simulator/jobRunErrors'; import { simulatorRequestFailureReason, simulatorRequestProperties, @@ -634,37 +638,16 @@ export default class Simulator extends EasCommand { } } -const JOB_RUN_ERRORS_TIMEOUT_MS = 10_000; -const MAX_JOB_RUN_ERROR_LENGTH = 500; - -// Returns the reasons the session's job run failed, one per line, or an empty string when none are -// available. Gives up after a deadline or when `signal` aborts, so it can't hold up stopping the session. +// Returns the reasons the session's job run failed, one per line, or an empty string when none are available. async function formatJobRunErrorsAsync( graphqlClient: ExpoGraphqlClient, deviceRunSessionId: string, signal: AbortSignal ): Promise { - if (signal.aborted) { - return ''; - } - let jobRun; - try { - jobRun = await DeviceRunSessionQuery.jobRunErrorsByIdAsync(graphqlClient, deviceRunSessionId, { - signal: AbortSignal.any([signal, AbortSignal.timeout(JOB_RUN_ERRORS_TIMEOUT_MS)]), - }); - } catch (err) { - Log.debug(`Failed to fetch simulator session errors: ${err}`); - return ''; - } - return (jobRun?.errors ?? []) - .map(error => { - const message = - error.message.length > MAX_JOB_RUN_ERROR_LENGTH - ? `${error.message.slice(0, MAX_JOB_RUN_ERROR_LENGTH)}…` - : error.message; - return `\n${message}${error.docsUrl ? ` ${learnMore(error.docsUrl)}` : ''}`; - }) - .join(''); + const errors = await fetchSimulatorSessionErrorsAsync(graphqlClient, deviceRunSessionId, { + signal, + }); + return errors.map(error => `\n${formatSimulatorSessionError(error)}`).join(''); } async function resolvePlatformAsync( diff --git a/packages/eas-cli/src/graphql/generated.ts b/packages/eas-cli/src/graphql/generated.ts index b090fda0d1..c81351929d 100644 --- a/packages/eas-cli/src/graphql/generated.ts +++ b/packages/eas-cli/src/graphql/generated.ts @@ -16023,7 +16023,7 @@ export type DeviceRunSessionJobRunErrorsByIdQueryVariables = Exact<{ }>; -export type DeviceRunSessionJobRunErrorsByIdQuery = { __typename?: 'RootQuery', deviceRunSessions: { __typename?: 'DeviceRunSessionQuery', byId: { __typename?: 'DeviceRunSession', id: string, turtleJobRun?: { __typename?: 'JobRun', id: string, errors: Array<{ __typename?: 'JobRunError', errorCode: string, message: string, docsUrl?: string | null }> } | null } } }; +export type DeviceRunSessionJobRunErrorsByIdQuery = { __typename?: 'RootQuery', deviceRunSessions: { __typename?: 'DeviceRunSessionQuery', byId: { __typename?: 'DeviceRunSession', id: string, turtleJobRun?: { __typename?: 'JobRun', id: string, logFileUrls: Array, errors: Array<{ __typename?: 'JobRunError', errorCode: string, message: string, docsUrl?: string | null }> } | null } } }; export type DeviceRunSessionByIdQueryVariables = Exact<{ deviceRunSessionId: Scalars['ID']['input']; diff --git a/packages/eas-cli/src/graphql/queries/DeviceRunSessionQuery.ts b/packages/eas-cli/src/graphql/queries/DeviceRunSessionQuery.ts index 1dad63122c..43f8e9d3da 100644 --- a/packages/eas-cli/src/graphql/queries/DeviceRunSessionQuery.ts +++ b/packages/eas-cli/src/graphql/queries/DeviceRunSessionQuery.ts @@ -71,6 +71,7 @@ export const DeviceRunSessionQuery = { message docsUrl } + logFileUrls } } } diff --git a/packages/eas-cli/src/graphql/queries/__tests__/DeviceRunSessionQuery-test.ts b/packages/eas-cli/src/graphql/queries/__tests__/DeviceRunSessionQuery-test.ts index e37d6fb272..3debcbd29b 100644 --- a/packages/eas-cli/src/graphql/queries/__tests__/DeviceRunSessionQuery-test.ts +++ b/packages/eas-cli/src/graphql/queries/__tests__/DeviceRunSessionQuery-test.ts @@ -46,6 +46,7 @@ describe('DeviceRunSessionQuery.jobRunErrorsByIdAsync', () => { const turtleJobRun = { __typename: 'JobRun', id: 'job-123', + logFileUrls: ['https://logs.example.com/job-123'], errors: [ { __typename: 'JobRunError', diff --git a/packages/eas-cli/src/simulator/__tests__/jobRunErrors.test.ts b/packages/eas-cli/src/simulator/__tests__/jobRunErrors.test.ts new file mode 100644 index 0000000000..4ca683db6a --- /dev/null +++ b/packages/eas-cli/src/simulator/__tests__/jobRunErrors.test.ts @@ -0,0 +1,479 @@ +import http from 'http'; +import { AddressInfo } from 'net'; + +import { ExpoGraphqlClient } from '../../commandUtils/context/contextUtils/createGraphqlClient'; +import { DeviceRunSessionQuery } from '../../graphql/queries/DeviceRunSessionQuery'; +import type LogType from '../../log'; +import type * as JobRunErrors from '../jobRunErrors'; + +jest.mock('../../graphql/queries/DeviceRunSessionQuery'); +jest.mock('../../log'); + +const mockJobRunErrorsByIdAsync = jest.mocked(DeviceRunSessionQuery.jobRunErrorsByIdAsync); +const graphqlClient = {} as ExpoGraphqlClient; +const unknownError = { + errorCode: 'UNKNOWN_ERROR', + message: 'Unknown error. See logs for more information.', + docsUrl: null, +}; + +// src/fetch.ts reads https_proxy when it loads, so load it only after clearing the proxy. +let jobRunErrors: typeof JobRunErrors; +let Log: typeof LogType; +beforeAll(() => { + delete process.env.https_proxy; + jest.isolateModules(() => { + jobRunErrors = jest.requireActual('../jobRunErrors'); + Log = jest.requireMock('../../log').default; + }); +}); + +// Lines 116-121 of a real failed Android session log, trimmed. The step's stderr has the precise +// cause at level 30; the level-50 error line only has the exit code. +const failedLaunchLog = [ + { + level: 30, + buildStepId: 'install_build', + marker: 'end-step', + result: 'success', + msg: 'Finished build step "Install build" successfully', + }, + { + level: 30, + buildStepId: 'install_build', + source: 'stderr', + msg: 'Error: Unable to find emulator skin, using default', + }, + { + level: 30, + buildStepId: 'step-002', + buildStepDisplayName: 'Launch application', + marker: 'start-step', + msg: 'Executing build step "Launch application"', + }, + { + level: 30, + buildStepId: 'step-002', + buildStepDisplayName: 'Launch application', + source: 'stdout', + msg: 'Starting: Intent { act=android.intent.action.MAIN pkg=world }', + }, + { + level: 30, + buildStepId: 'step-002', + buildStepDisplayName: 'Launch application', + source: 'stderr', + msg: 'Error: Activity not started, unable to resolve Intent { act=android.intent.action.MAIN pkg=world }', + }, + { + level: 50, + buildStepId: 'step-002', + buildStepDisplayName: 'Launch application', + msg: 'adb shell am start -n dev.brent.euxy/.MainActivity exited with non-zero code: 1', + err: { + message: 'adb shell am start -n dev.brent.euxy/.MainActivity exited with non-zero code: 1', + }, + }, + { + level: 50, + buildStepId: 'step-002', + buildStepDisplayName: 'Launch application', + marker: 'end-step', + result: 'fail', + msg: 'Build step "Launch application" failed', + }, +]; + +describe('selectFailedStepErrors', () => { + it("shows the failed step's stderr cause before its error line", () => { + expect(jobRunErrors.selectFailedStepErrors(failedLaunchLog)).toEqual([ + 'Launch application: Error: Activity not started, unable to resolve Intent { act=android.intent.action.MAIN pkg=world }', + 'Launch application: adb shell am start -n dev.brent.euxy/.MainActivity exited with non-zero code: 1', + ]); + }); + + it('ignores stderr from steps that did not fail', () => { + const messages = jobRunErrors.selectFailedStepErrors(failedLaunchLog); + expect(messages.join('\n')).not.toContain('emulator skin'); + }); + + it('never prints the unmasked err.message of a phase failure with an empty message', () => { + const phaseFailureLog = [ + { level: 30, phase: 'PREPARE_PROJECT', msg: 'Start phase: PREPARE_PROJECT' }, + { + level: 50, + phase: 'PREPARE_PROJECT', + msg: '', + err: { + message: 'git clone https://secret-token@github.com/acme/app failed', + stack: 'Error: git clone https://secret-token@github.com/acme/app failed', + }, + }, + ]; + expect(jobRunErrors.selectFailedStepErrors(phaseFailureLog)).toEqual([]); + }); + + it('ignores errors outside of failed steps, such as errors a step ignored', () => { + expect( + jobRunErrors.selectFailedStepErrors([ + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Upload artifact', + msg: 'Failed to upload screen-recording. Ignoring error.', + err: { message: 'upload failed' }, + }, + { + level: 30, + buildStepId: 'step-001', + marker: 'end-step', + result: 'success', + msg: 'Finished', + }, + { + level: 50, + msg: 'simctl boot failed for ********', + err: { message: 'simctl boot failed for secret-udid' }, + }, + ]) + ).toEqual([]); + }); + + it('keeps the stderr line that continues the cause', () => { + expect( + jobRunErrors.selectFailedStepErrors([ + { + level: 30, + buildStepId: 'step-001', + buildStepDisplayName: 'Boot simulator', + source: 'stderr', + msg: 'An error was encountered processing the command (domain=com.apple.CoreSimulator.SimError, code=405):', + }, + { + level: 30, + buildStepId: 'step-001', + buildStepDisplayName: 'Boot simulator', + source: 'stderr', + msg: 'Invalid device: iPhone 16 Pro', + }, + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Boot simulator', + msg: 'xcrun simctl boot exited with non-zero code: 149', + err: { message: 'xcrun simctl boot exited with non-zero code: 149' }, + }, + { + level: 50, + buildStepId: 'step-001', + marker: 'end-step', + result: 'fail', + msg: 'Build step "Boot simulator" failed', + }, + ]) + ).toEqual([ + 'Boot simulator: An error was encountered processing the command (domain=com.apple.CoreSimulator.SimError, code=405):', + 'Boot simulator: Invalid device: iPhone 16 Pro', + 'Boot simulator: xcrun simctl boot exited with non-zero code: 149', + ]); + }); + + it('keeps the cause of the first failed step when later steps also fail', () => { + expect( + jobRunErrors.selectFailedStepErrors([ + ...failedLaunchLog, + { + level: 30, + buildStepId: 'step-003', + buildStepDisplayName: 'Finish recordings', + source: 'stderr', + msg: 'Error: No devices are booted.', + }, + { + level: 50, + buildStepId: 'step-003', + buildStepDisplayName: 'Finish recordings', + msg: 'xcrun simctl io recordVideo exited with non-zero code: 1', + err: { message: 'x' }, + }, + { + level: 50, + buildStepId: 'step-003', + marker: 'end-step', + result: 'fail', + msg: 'Build step "Finish recordings" failed', + }, + ]) + ).toEqual([ + 'Launch application: Error: Activity not started, unable to resolve Intent { act=android.intent.action.MAIN pkg=world }', + 'Launch application: adb shell am start -n dev.brent.euxy/.MainActivity exited with non-zero code: 1', + 'Finish recordings: xcrun simctl io recordVideo exited with non-zero code: 1', + ]); + }); + + it('strips escape sequences and control characters from step names and messages', () => { + expect( + jobRunErrors.selectFailedStepErrors([ + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Boot\u001b[2J simulator', + msg: '\u001b[31mxcrun simctl boot\u001b[0m exited\r\nwith code: 149\u0007', + err: { message: 'x' }, + }, + { + level: 50, + buildStepId: 'step-001', + marker: 'end-step', + result: 'fail', + msg: 'Build step "Boot simulator" failed', + }, + ]) + ).toEqual(['Boot simulator: xcrun simctl boot exited with code: 149']); + }); + + it('finds a colored stderr cause and skips error lines that are only escape sequences', () => { + expect( + jobRunErrors.selectFailedStepErrors([ + { + level: 30, + buildStepId: 'step-001', + buildStepDisplayName: 'Launch application', + source: 'stderr', + msg: '\u001b[31mError\u001b[0m: Activity not started', + }, + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Launch application', + msg: 'adb shell am start exited with non-zero code: 1', + err: { message: 'x' }, + }, + { + level: 50, + buildStepId: 'step-001', + buildStepDisplayName: 'Launch application', + msg: '\u001b[0m\u001b[K', + err: { message: 'x' }, + }, + { + level: 50, + buildStepId: 'step-001', + marker: 'end-step', + result: 'fail', + msg: 'Build step "Launch application" failed', + }, + ]) + ).toEqual([ + 'Launch application: Error: Activity not started', + 'Launch application: adb shell am start exited with non-zero code: 1', + ]); + }); +}); + +describe('fetchSimulatorSessionErrorsAsync', () => { + let server: http.Server; + let closedRequests: number; + + async function startServerAsync(handler: http.RequestListener): Promise { + closedRequests = 0; + server = http.createServer((request, response) => { + request.socket.on('close', () => { + closedRequests += 1; + }); + handler(request, response); + }); + await new Promise(resolve => server.listen(0, '127.0.0.1', resolve)); + const { port } = server.address() as AddressInfo; + return `http://127.0.0.1:${port}/logs`; + } + + beforeEach(() => { + jest.clearAllMocks(); + }); + + async function waitForCloseAsync(): Promise { + for (let attempt = 0; attempt < 50 && closedRequests === 0; attempt++) { + await new Promise(resolve => setTimeout(resolve, 20)); + } + } + + afterEach(async () => { + server.closeAllConnections(); + await new Promise(resolve => server.close(resolve)); + }); + + function mockJobRun(logFileUrl: string): void { + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [unknownError], + logFileUrls: [logFileUrl], + }); + } + + it('returns the failed step errors from the downloaded log', async () => { + mockJobRun( + await startServerAsync((_request, response) => { + response.end(failedLaunchLog.map(line => JSON.stringify(line)).join('\n')); + }) + ); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123') + ).resolves.toEqual([ + { + errorCode: 'UNKNOWN_ERROR', + message: expect.stringContaining('Activity not started'), + docsUrl: null, + }, + { + errorCode: 'UNKNOWN_ERROR', + message: expect.stringContaining('exited with non-zero code: 1'), + docsUrl: null, + }, + ]); + }); + + it('does not log the signed log URL when the download fails', async () => { + const logFileUrl = await startServerAsync((request, response) => { + request.socket.destroy(); + response.end(); + }); + mockJobRun(`${logFileUrl}?X-Goog-Signature=secret-signature`); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123') + ).resolves.toEqual([unknownError]); + expect(JSON.stringify(jest.mocked(Log.debug).mock.calls)).not.toContain('secret-signature'); + }); + + it('strips escape sequences and control characters from job run error messages', async () => { + server = http.createServer(); + await new Promise(resolve => server.listen(0, '127.0.0.1', resolve)); + mockJobRunErrorsByIdAsync.mockResolvedValue({ + id: 'job-123', + errors: [ + { + errorCode: 'EAS_IOS_SIMULATOR_NOT_FOUND', + message: 'No available iOS Simulator is named "\u001b[2JiPhone\u001b]0;x\u0007\nFake"', + docsUrl: null, + }, + ], + logFileUrls: [], + }); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123') + ).resolves.toEqual([ + { + errorCode: 'EAS_IOS_SIMULATOR_NOT_FOUND', + message: 'No available iOS Simulator is named "iPhone Fake"', + docsUrl: null, + }, + ]); + }); + + it('falls back to the job run error when the log request fails', async () => { + mockJobRun( + await startServerAsync((_request, response) => { + response.statusCode = 404; + response.end(JSON.stringify({ level: 50, msg: 'not the cause', err: { message: 'x' } })); + }) + ); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123') + ).resolves.toEqual([unknownError]); + }); + + it('falls back and closes the connection when the log is too large', async () => { + mockJobRun( + await startServerAsync((_request, response) => { + const chunk = 'x'.repeat(64 * 1024); + const timer = setInterval(() => response.write(chunk), 5); + response.on('close', () => { + clearInterval(timer); + }); + }) + ); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123', { + maxLogSizeBytes: 256 * 1024, + }) + ).resolves.toEqual([unknownError]); + await waitForCloseAsync(); + expect(closedRequests).toBe(1); + }); + + it('falls back and closes the connection when the log download stalls', async () => { + mockJobRun( + await startServerAsync((_request, response) => { + response.write('{"level":30,'); + }) + ); + + const startedAt = Date.now(); + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123', { + logDownloadTimeoutMs: 200, + }) + ).resolves.toEqual([unknownError]); + expect(Date.now() - startedAt).toBeLessThan(2_000); + await waitForCloseAsync(); + expect(closedRequests).toBe(1); + }); + + it('stops the log download when the signal aborts', async () => { + mockJobRun( + await startServerAsync((_request, response) => { + response.write('{"level":30,'); + }) + ); + const controller = new AbortController(); + setTimeout(() => { + controller.abort(); + }, 100); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123', { + signal: controller.signal, + }) + ).resolves.toEqual([unknownError]); + await waitForCloseAsync(); + expect(closedRequests).toBe(1); + }); + + it('does not look up errors when the signal has already aborted', async () => { + server = http.createServer(); + await new Promise(resolve => server.listen(0, '127.0.0.1', resolve)); + const controller = new AbortController(); + controller.abort(); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123', { + signal: controller.signal, + }) + ).resolves.toEqual([]); + expect(mockJobRunErrorsByIdAsync).not.toHaveBeenCalled(); + }); + + it('passes an abortable signal with a deadline to the errors query', async () => { + server = http.createServer(); + await new Promise(resolve => server.listen(0, '127.0.0.1', resolve)); + mockJobRunErrorsByIdAsync.mockImplementation( + async (_client, _id, { signal }) => + await new Promise((_resolve, reject) => { + signal.addEventListener('abort', () => { + reject(signal.reason); + }); + }) + ); + + await expect( + jobRunErrors.fetchSimulatorSessionErrorsAsync(graphqlClient, 'session-123', { + queryTimeoutMs: 100, + }) + ).resolves.toEqual([]); + }); +}); diff --git a/packages/eas-cli/src/simulator/jobRunErrors.ts b/packages/eas-cli/src/simulator/jobRunErrors.ts new file mode 100644 index 0000000000..cdf84ddba9 --- /dev/null +++ b/packages/eas-cli/src/simulator/jobRunErrors.ts @@ -0,0 +1,172 @@ +import { stripVTControlCharacters } from 'util'; + +import { ExpoGraphqlClient } from '../commandUtils/context/contextUtils/createGraphqlClient'; +import { parseLogLines } from '../commandUtils/logs/parseLogs'; +import { RawLogLine } from '../commandUtils/logs/types'; +import fetch from '../fetch'; +import { DeviceRunSessionQuery } from '../graphql/queries/DeviceRunSessionQuery'; +import Log, { learnMore } from '../log'; +import { sanitizeTerminalText } from '../utils/terminalText'; + +export type SimulatorSessionError = { + errorCode: string; + message: string; + docsUrl?: string | null; +}; + +export type FetchSimulatorSessionErrorsOptions = { + /** Aborts the lookup, e.g. on Ctrl+C. */ + signal?: AbortSignal; + queryTimeoutMs?: number; + logDownloadTimeoutMs?: number; + maxLogSizeBytes?: number; +}; + +// ErrorCode.UNKNOWN_ERROR and ErrorCode.UNKNOWN_CUSTOM_BUILD_ERROR from @expo/eas-build-job. +const UNKNOWN_ERROR_CODES = new Set(['UNKNOWN_ERROR', 'UNKNOWN_CUSTOM_BUILD_ERROR']); +const DEFAULT_QUERY_TIMEOUT_MS = 10_000; +const DEFAULT_LOG_DOWNLOAD_TIMEOUT_MS = 10_000; +const DEFAULT_MAX_LOG_SIZE_BYTES = 20 * 1024 * 1024; +const MAX_LOGGED_ERRORS = 4; +const MAX_LOGGED_ERROR_LENGTH = 500; +// Bunyan's "error" level. +const ERROR_LOG_LEVEL = 50; +const STDERR_CAUSE_PATTERN = /\b(error|exception|fatal)\b/i; + +type JobRunLogLine = RawLogLine & { level?: number; source?: string }; + +// Returns why the session's job run failed, or an empty list when that is not available. +export async function fetchSimulatorSessionErrorsAsync( + graphqlClient: ExpoGraphqlClient, + deviceRunSessionId: string, + { + signal, + queryTimeoutMs = DEFAULT_QUERY_TIMEOUT_MS, + logDownloadTimeoutMs = DEFAULT_LOG_DOWNLOAD_TIMEOUT_MS, + maxLogSizeBytes = DEFAULT_MAX_LOG_SIZE_BYTES, + }: FetchSimulatorSessionErrorsOptions = {} +): Promise { + if (signal?.aborted) { + return []; + } + let jobRun; + try { + jobRun = await DeviceRunSessionQuery.jobRunErrorsByIdAsync(graphqlClient, deviceRunSessionId, { + signal: withTimeout(signal, queryTimeoutMs), + }); + } catch (err) { + Log.debug(`Failed to fetch simulator session errors: ${err}`); + return []; + } + const errors = jobRun?.errors ?? []; + // Uncategorized failures only say "Unknown error. See logs", so read the real cause from the job run logs. + const logFileUrl = jobRun?.logFileUrls[0]; + if ( + logFileUrl && + errors.length > 0 && + errors.every(error => UNKNOWN_ERROR_CODES.has(error.errorCode)) + ) { + const logErrors = await fetchJobRunLogErrorsAsync(logFileUrl, { + signal: withTimeout(signal, logDownloadTimeoutMs), + maxLogSizeBytes, + }); + if (logErrors.length > 0) { + return logErrors.map(message => ({ errorCode: errors[0].errorCode, message, docsUrl: null })); + } + } + return errors.map(({ errorCode, message, docsUrl }) => ({ + errorCode, + message: formatMessage(message), + docsUrl, + })); +} + +export function formatSimulatorSessionError(error: SimulatorSessionError): string { + return `${error.message}${error.docsUrl ? ` ${learnMore(error.docsUrl)}` : ''}`; +} + +function withTimeout(signal: AbortSignal | undefined, timeoutMs: number): AbortSignal { + const timeoutSignal = AbortSignal.timeout(timeoutMs); + return signal ? AbortSignal.any([signal, timeoutSignal]) : timeoutSignal; +} + +async function fetchJobRunLogErrorsAsync( + logFileUrl: string, + { signal, maxLogSizeBytes }: { signal: AbortSignal; maxLogSizeBytes: number } +): Promise { + // node-fetch stops reading on its own only when the body ends, so abort to close the connection + // after an error, an oversized body or a timeout. + const controller = new AbortController(); + try { + const response = await fetch(logFileUrl, { + size: maxLogSizeBytes, + signal: AbortSignal.any([signal, controller.signal]), + }); + const { logLines } = parseLogLines(await response.text()); + return selectFailedStepErrors(logLines); + } catch (err) { + // node-fetch's error messages include the signed log URL, so leave the message out. + Log.debug( + `Failed to read simulator session logs: ${err instanceof Error ? err.name : 'unknown error'}` + ); + return []; + } finally { + controller.abort(); + } +} + +// Describes the steps that failed, the first one first: its last error line, preceded by the stderr +// line that names the cause and the line after it. Later failed steps only add their error line. +// Uses the log message rather than err.message because only the message has secrets masked. +export function selectFailedStepErrors(logLines: JobRunLogLine[]): string[] { + const failedStepIds = [ + ...new Set( + logLines + .filter(line => line.marker === 'end-step' && line.result === 'fail' && line.buildStepId) + .map(line => line.buildStepId as string) + ), + ]; + const messages = failedStepIds.flatMap((stepId, index) => { + const lines = selectStepFailureLines(logLines.filter(line => line.buildStepId === stepId)); + return (index === 0 ? lines : lines.slice(-1)).map(formatLogLine); + }); + return [...new Set(messages)].slice(0, MAX_LOGGED_ERRORS); +} + +function selectStepFailureLines(stepLines: JobRunLogLine[]): JobRunLogLine[] { + let selected: JobRunLogLine[] = []; + let stderrCause: JobRunLogLine[] = []; + for (const [index, line] of stepLines.entries()) { + const text = toPlainText(line.msg ?? ''); + if (line.source === 'stderr') { + if (STDERR_CAUSE_PATTERN.test(text)) { + stderrCause = [line]; + } else if (stderrCause.length === 1 && stepLines[index - 1] === stderrCause[0]) { + stderrCause.push(line); + } + } else if (line.err && (line.level ?? 0) >= ERROR_LOG_LEVEL && text) { + selected = [...stderrCause, line]; + stderrCause = []; + } + } + return selected; +} + +function formatLogLine(line: JobRunLogLine): string { + return formatMessage( + line.buildStepDisplayName ? `${line.buildStepDisplayName}: ${line.msg}` : String(line.msg) + ); +} + +// Log text comes from commands run in the session, so strip escape sequences and control +// characters that could clear the terminal or spoof output. +function toPlainText(message: string): string { + return sanitizeTerminalText(stripVTControlCharacters(message)); +} + +function formatMessage(message: string): string { + const text = toPlainText(message); + return text.length > MAX_LOGGED_ERROR_LENGTH + ? `${text.slice(0, MAX_LOGGED_ERROR_LENGTH)}…` + : text; +}