[build-tools] [ENG-15188] Cancel hanging workflows

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);
   });

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);
+  }
+}

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<typeof FunctionStepZ>;
@@ -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(),

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<void> {
     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`);
   }

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'],
     });
   }
 

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();
     });
   });
 });

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<SpawnOptionsOriginal, 'stdio' | 'ignoreStdio'> & {
-  lineTransformer?: (line: string) => string | null;
-  mode?: PipeMode;
-} & (
+type SpawnOptions = Omit<SpawnOptionsOriginal, 'stdio' | 'ignoreStdio'> &
+  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<SpawnResult> {
-  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<SpawnResult>
+  ): 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;
 }