diff --git a/packages/eas-build-job/src/__tests__/step.test.ts b/packages/eas-build-job/src/__tests__/step.test.ts index d64d74828..636cead95 100644 --- a/packages/eas-build-job/src/__tests__/step.test.ts +++ b/packages/eas-build-job/src/__tests__/step.test.ts @@ -66,6 +66,8 @@ describe('StepZ', () => { env: { KEY1: 'value1', }, + 'no-logs-warn-timeout-minutes': 15, + 'no-logs-kill-timeout-minutes': 30, }; expect(StepZ.parse(step)).toEqual(step); }); diff --git a/packages/eas-build-job/src/errors.ts b/packages/eas-build-job/src/errors.ts index 3156bdef5..92015ba6f 100644 --- a/packages/eas-build-job/src/errors.ts +++ b/packages/eas-build-job/src/errors.ts @@ -103,3 +103,10 @@ export class CredentialsDistCertMismatchError extends UserFacingError { super('EAS_BUILD_CREDENTIALS_DIST_CERT_MISMATCH', message); } } + +export class SpawnCommandTimeoutError extends UserFacingError { + constructor(message?: string | undefined) { + const defaultMessage = 'Command timed out.'; + super('EAS_BUILD_SPAWN_COMMAND_TIMEOUT', message ?? defaultMessage); + } +} diff --git a/packages/eas-build-job/src/step.ts b/packages/eas-build-job/src/step.ts index afdb71fa4..494ada67a 100644 --- a/packages/eas-build-job/src/step.ts +++ b/packages/eas-build-job/src/step.ts @@ -87,6 +87,8 @@ export const FunctionStepZ = CommonStepZ.extend({ run: z.never().optional(), shell: z.never().optional(), outputs: z.never().optional(), + 'no-logs-warn-timeout-minutes': z.never().optional(), + 'no-logs-kill-timeout-minutes': z.never().optional(), }); export type FunctionStep = z.infer; @@ -137,6 +139,30 @@ export const ShellStepZ = CommonStepZ.extend({ ]) ) .optional(), + /** + * Number of minutes since last log produced by the script, after which a warning will be logged. + * + * @example + * no-logs-warn-timeout-minutes: 15 + */ + 'no-logs-warn-timeout-minutes': z + .number() + .optional() + .describe( + 'If the script does not produce any logs in this many minutes, a warning will be logged.' + ), + /** + * Number of minutes since last log produced by the script, after which an error will be thrown and the process running the script will be terminated. + * + * @example + * no-logs-kill-timeout-minutes: 30 + */ + 'no-logs-kill-timeout-minutes': z + .number() + .optional() + .describe( + 'If the script does not produce any logs in this many minutes, an error will be thrown and script will be terminated.' + ), uses: z.never().optional(), with: z.never().optional(), diff --git a/packages/steps/src/BuildStep.ts b/packages/steps/src/BuildStep.ts index 7d88462e4..0dd6d270c 100644 --- a/packages/steps/src/BuildStep.ts +++ b/packages/steps/src/BuildStep.ts @@ -4,7 +4,7 @@ import path from 'path'; import { Buffer } from 'buffer'; import { v4 as uuidv4 } from 'uuid'; -import { JobInterpolationContext } from '@expo/eas-build-job'; +import { JobInterpolationContext, errors } from '@expo/eas-build-job'; import { BuildStepContext, BuildStepGlobalContext } from './BuildStepContext.js'; import { BuildStepInput, BuildStepInputById, makeBuildStepInputByIdMap } from './BuildStepInput.js'; @@ -57,6 +57,8 @@ export type BuildStepFunction = ( const UUID_REGEX = /^[0-9a-fA-F]{8}\b-[0-9a-fA-F]{4}\b-[0-9a-fA-F]{4}\b-[0-9a-fA-F]{4}\b-[0-9a-fA-F]{12}$/; +class BuildStepTimeoutError extends errors.SpawnCommandTimeoutError {} + export interface SerializedBuildStepOutputAccessor { id: string; executed: boolean; @@ -142,6 +144,9 @@ export class BuildStep extends BuildStepOutputAccessor { private readonly inputById: BuildStepInputById; protected executed = false; + public readonly noLogsWarnTimeoutMinutes?: number; + public readonly noLogsKillTimeoutMinutes?: number; + public static getNewId(userDefinedId?: string): string { return userDefinedId ?? uuidv4(); } @@ -188,6 +193,8 @@ export class BuildStep extends BuildStepOutputAccessor { supportedRuntimePlatforms: maybeSupportedRuntimePlatforms, env, ifCondition, + noLogsWarnTimeoutMinutes, + noLogsKillTimeoutMinutes, }: { id: string; name?: string; @@ -201,6 +208,8 @@ export class BuildStep extends BuildStepOutputAccessor { supportedRuntimePlatforms?: BuildRuntimePlatform[]; env?: BuildStepEnv; ifCondition?: string; + noLogsWarnTimeoutMinutes?: number; + noLogsKillTimeoutMinutes?: number; } ) { assert(command !== undefined || fn !== undefined, 'Either command or fn must be defined.'); @@ -234,6 +243,9 @@ export class BuildStep extends BuildStepOutputAccessor { this.outputsDir = getTemporaryOutputsDirPath(ctx, this.id); this.envsDir = getTemporaryEnvsDirPath(ctx, this.id); + this.noLogsWarnTimeoutMinutes = noLogsWarnTimeoutMinutes; + this.noLogsKillTimeoutMinutes = noLogsKillTimeoutMinutes; + ctx.registerStep(this); } @@ -360,6 +372,7 @@ export class BuildStep extends BuildStepOutputAccessor { toJSON: (value: unknown) => JSON.stringify(value), }; } + private async executeCommandAsync(): Promise { assert(this.command, 'Command must be defined.'); @@ -387,6 +400,21 @@ export class BuildStep extends BuildStepOutputAccessor { env: this.getScriptEnv(), // stdin is /dev/null, std{out,err} are piped into logger. stdio: ['ignore', 'pipe', 'pipe'], + noLogsTimeout: { + warn: { + timeoutMinutes: this.noLogsWarnTimeoutMinutes ?? 15, + message: + 'Command takes longer then expected and it did not produce any logs in the past 15 minutes. Consider evaluating your command for possible issues.', + }, + kill: { + timeoutMinutes: this.noLogsKillTimeoutMinutes ?? 30, + message: + 'Command takes a very long time and it did not produce any logs in the past 30 minutes. Most likely an unexpected error happened which caused the process to hang and it will be terminated.', + errorClass: BuildStepTimeoutError, + errorMessage: + 'Command was inactive for over 30 minutes. Please evaluate if it is correct.', + }, + }, }); this.ctx.logger.debug(`Script completed successfully`); } diff --git a/packages/steps/src/StepsConfigParser.ts b/packages/steps/src/StepsConfigParser.ts index db3996c4d..4240a92c3 100644 --- a/packages/steps/src/StepsConfigParser.ts +++ b/packages/steps/src/StepsConfigParser.ts @@ -128,6 +128,8 @@ export class StepsConfigParser extends AbstractConfigParser { command: step.run, env: step.env, ifCondition: step.if, + noLogsWarnTimeoutMinutes: step['no-logs-warn-timeout-minutes'], + noLogsKillTimeoutMinutes: step['no-logs-kill-timeout-minutes'], }); } diff --git a/packages/steps/src/__tests__/StepsConfigParser-test.ts b/packages/steps/src/__tests__/StepsConfigParser-test.ts index 2410f52d1..3c847fd22 100644 --- a/packages/steps/src/__tests__/StepsConfigParser-test.ts +++ b/packages/steps/src/__tests__/StepsConfigParser-test.ts @@ -195,6 +195,8 @@ describe(StepsConfigParser, () => { }, ], if: '${ always() }', + 'no-logs-warn-timeout-minutes': 5, + 'no-logs-kill-timeout-minutes': 10, }, { id: 'step4', @@ -322,6 +324,8 @@ describe(StepsConfigParser, () => { expect(output3.id).toBe('my_optional_output_without_required'); expect(output3.required).toBe(true); expect(step3.ifCondition).toBe('${ always() }'); + expect(step3.noLogsWarnTimeoutMinutes).toBe(5); + expect(step3.noLogsKillTimeoutMinutes).toBe(10); const step4 = result.buildSteps[3]; expect(step4.id).toEqual('step4'); @@ -370,6 +374,8 @@ describe(StepsConfigParser, () => { expect(input4.required).toBe(true); expect(step4.outputById).toStrictEqual({}); expect(step4.ifCondition).toBe('${ ctx.job.platform } == "android"'); + expect(step4.noLogsWarnTimeoutMinutes).toBeUndefined(); + expect(step4.noLogsKillTimeoutMinutes).toBeUndefined(); }); }); }); diff --git a/packages/steps/src/utils/shell/spawn.ts b/packages/steps/src/utils/shell/spawn.ts index 47f57e2c1..2f59666e7 100644 --- a/packages/steps/src/utils/shell/spawn.ts +++ b/packages/steps/src/utils/shell/spawn.ts @@ -1,31 +1,90 @@ import { IOType } from 'child_process'; -import { pipeSpawnOutput, bunyan, PipeMode } from '@expo/logger'; +import { pipeSpawnOutput, bunyan, PipeOptions } from '@expo/logger'; import spawnAsyncOriginal, { SpawnResult, SpawnPromise, SpawnOptions as SpawnOptionsOriginal, } from '@expo/spawn-async'; +import { errors } from '@expo/eas-build-job'; + +import { nullthrows } from '../nullthrows.js'; + +interface IErrorClass { + new (message?: string | undefined): errors.SpawnCommandTimeoutError; +} + +type NoLogsTimeoutOptions = { + warn?: { + timeoutMinutes?: number; + message?: string; + }; + kill?: { + timeoutMinutes?: number; + message?: string; + errorClass?: IErrorClass; + errorMessage?: string; + }; +}; // We omit 'ignoreStdio' to simplify logic -- only 'stdio' governs stdio. // We omit 'stdio' here to add further down in a logger-based union. -type SpawnOptions = Omit & { - lineTransformer?: (line: string) => string | null; - mode?: PipeMode; -} & ( +type SpawnOptions = Omit & + PipeOptions & + ( | { // If logger is passed, we require stdio to be pipe. logger: bunyan; stdio: 'pipe' | [IOType, 'pipe', 'pipe', ...IOType[]]; + noLogsTimeout?: NoLogsTimeoutOptions; } | { // If logger is not passed, stdio can be anything. // Defaults to inherit. logger?: never; stdio?: SpawnOptionsOriginal['stdio']; + noLogsTimeout?: undefined; } ); -// If + +const SPAWN_WARN_TIMEOUT_DEFAULT_MINUTES = 15; +const SPAWN_WARN_TIMEOUT_DEFAULT_MESSAGE = + 'Command takes longer then expected and it did not produce any logs in the past ${minutes} minutes. Consider evaluating your command for possible issues.'; +const SPAWN_KILL_TIMEOUT_DEFAULT_MINUTES = 30; +const SPAWN_KILL_TIMEOUT_DEFAULT_MESSAGE = + 'Command takes a very long time and it did not produce any logs in the past ${minutes} minutes. Most likely an unexpected error happened which caused the process to hang and it will be terminated.'; +const SPAWN_KILL_TIMEOUT_DEFAULT_ERROR_MESSAGE = + 'Command was inactive for over ${minutes} minutes. Please evaluate if it is correct.'; + +function getWarnTimeoutMessage(noLogsTimeout: NoLogsTimeoutOptions): string { + const warnTimeoutMinutes = + noLogsTimeout.warn?.timeoutMinutes ?? SPAWN_WARN_TIMEOUT_DEFAULT_MINUTES; + return ( + noLogsTimeout.warn?.message ?? + SPAWN_WARN_TIMEOUT_DEFAULT_MESSAGE.replace('${minutes}', warnTimeoutMinutes.toString()) + ); +} + +function getKillTimeoutMessage(noLogsTimeout: NoLogsTimeoutOptions): string { + const killTimeoutMinutes = + noLogsTimeout.kill?.timeoutMinutes ?? SPAWN_KILL_TIMEOUT_DEFAULT_MINUTES; + return ( + noLogsTimeout.kill?.message ?? + SPAWN_KILL_TIMEOUT_DEFAULT_MESSAGE.replace('${minutes}', killTimeoutMinutes.toString()) + ); +} + +function getKillTimeoutError( + noLogsTimeout: NoLogsTimeoutOptions | undefined +): errors.SpawnCommandTimeoutError { + const spawnKillTimeout = + noLogsTimeout?.kill?.timeoutMinutes ?? SPAWN_KILL_TIMEOUT_DEFAULT_MINUTES; + const errorMessage = + noLogsTimeout?.kill?.errorMessage ?? + SPAWN_KILL_TIMEOUT_DEFAULT_ERROR_MESSAGE.replace('${minutes}', spawnKillTimeout.toString()); + const ErrorClass = noLogsTimeout?.kill?.errorClass ?? errors.SpawnCommandTimeoutError; + return new ErrorClass(errorMessage); +} // eslint-disable-next-line async-protect/async-suffix export function spawnAsync( @@ -36,10 +95,81 @@ export function spawnAsync( cwd: process.cwd(), } ): SpawnPromise { - const { logger, ...options } = allOptions; - const promise = spawnAsyncOriginal(command, args, options); - if (logger && promise.child) { - pipeSpawnOutput(logger, promise.child, options); + const { logger, noLogsTimeout, ...options } = allOptions; + let spawnWarnTimeout: NodeJS.Timeout | undefined; + let spawnKillTimeout: NodeJS.Timeout | undefined; + let spawnTimedOut: boolean = false; + + function setCommandSpawnTimeouts( + noLogsTimeout: NoLogsTimeoutOptions, + logger: bunyan, + spawnPromise: SpawnPromise + ): void { + if (noLogsTimeout.warn) { + const warnTimeoutMinutes = + noLogsTimeout.warn.timeoutMinutes ?? SPAWN_WARN_TIMEOUT_DEFAULT_MINUTES; + spawnWarnTimeout = setTimeout( + () => { + logger.warn(getWarnTimeoutMessage(noLogsTimeout)); + }, + warnTimeoutMinutes * 60 * 1000 + ); + } + + if (noLogsTimeout.kill) { + const killTimeoutMinutes = + noLogsTimeout.kill.timeoutMinutes ?? SPAWN_KILL_TIMEOUT_DEFAULT_MINUTES; + spawnKillTimeout = setTimeout( + async () => { + spawnTimedOut = true; + logger.error(getKillTimeoutMessage(noLogsTimeout)); + const ppid = nullthrows(spawnPromise.child.pid); + process.kill(ppid); + }, + killTimeoutMinutes * 60 * 1000 + ); + } + } + + const spawnPromise = spawnAsyncOriginal(command, args, options); + if (logger && spawnPromise.child) { + if (noLogsTimeout) { + const optionsWithCallback = { + ...options, + infoCallbackFn: () => { + if (spawnWarnTimeout) { + spawnWarnTimeout.refresh(); + } + if (spawnKillTimeout) { + spawnKillTimeout.refresh(); + } + }, + }; + pipeSpawnOutput(logger, spawnPromise.child, optionsWithCallback); + setCommandSpawnTimeouts(noLogsTimeout, logger, spawnPromise); + } else { + pipeSpawnOutput(logger, spawnPromise.child, options); + } } - return promise; + spawnPromise + .then( + (spawnResult) => spawnResult, + (_) => {} + ) + .catch((err: any) => { + if (spawnTimedOut) { + throw getKillTimeoutError(noLogsTimeout); + } + throw err; + }) + .finally(() => { + if (spawnWarnTimeout) { + clearTimeout(spawnWarnTimeout); + } + if (spawnKillTimeout) { + clearTimeout(spawnKillTimeout); + } + }); + + return spawnPromise; }