Repository: wix/Detox
Pull request #2716 (2021-04-07 16:28:15)

fix(artifacts): more aggressive interruptProcess()
## Description

Internal change. Addresses rare conditions on a busy CI agent with unstable video recording commands.

1. `interruptProcess` now accepts a schedule of signals. For example:

```js
await interruptProcess(myChildProcessPromise, {
  SIGINT: 0, // first try gently, with SIGINT
  SIGTERM: 1000, // if is running after 1s, send SIGTERM
  SIGKILL: 5000, // if it is still running after 5s, 💀 
});
```

2. Simplified code in `SimulatorLogRecording` (reusing 1).
3. Added a forceful exit in `SimulatorRecordVideoPlugin` — should unblock the flow of artifacts saving.


Patch:
diff --git a/detox/package.json b/detox/package.json
index 758a75a4f..ec0a38c91 100644
--- a/detox/package.json
+++ b/detox/package.json
@@ -30,6 +30,7 @@
     "postinstall": "node scripts/postinstall.js"
   },
   "devDependencies": {
+    "@types/child-process-promise": "^2.2.1",
     "@types/ws": "^7.4.0",
     "eslint": "^4.11.0",
     "eslint-plugin-node": "^6.0.1",
diff --git a/detox/src/artifacts/log/ios/SimulatorLogRecording.js b/detox/src/artifacts/log/ios/SimulatorLogRecording.js
index 781fddd38..2a35a28c5 100644
--- a/detox/src/artifacts/log/ios/SimulatorLogRecording.js
+++ b/detox/src/artifacts/log/ios/SimulatorLogRecording.js
@@ -55,14 +55,10 @@ class SimulatorLogRecording extends Artifact {
   }
 
   async _tryInterruptProcessGracefully(process) {
-    const graceful = await Promise.race([
-      sleep(this._config.delayBeforeSigterm).then(() => false),
-      exec.interruptProcess(process, 'SIGINT').then(() => true),
-    ]);
-
-    if (!graceful) {
-      await exec.interruptProcess(process, 'SIGTERM');
-    }
+    await exec.interruptProcess(process, {
+      SIGINT: 0,
+      SIGTERM: this._config.delayBeforeSigterm,
+    });
   }
 
   async doSave(artifactPath) {
diff --git a/detox/src/artifacts/video/SimulatorRecordVideoPlugin.js b/detox/src/artifacts/video/SimulatorRecordVideoPlugin.js
index 7cd908449..d706ff856 100644
--- a/detox/src/artifacts/video/SimulatorRecordVideoPlugin.js
+++ b/detox/src/artifacts/video/SimulatorRecordVideoPlugin.js
@@ -25,7 +25,11 @@ class SimulatorRecordVideoPlugin extends VideoArtifactPlugin {
       },
       stop: async () => {
         if (processPromise) {
-          await interruptProcess(processPromise);
+          await interruptProcess(processPromise, {
+            SIGINT: 0,
+            SIGTERM: 5000,
+            SIGKILL: 6000,
+          });
         }
       },
       save: async (artifactPath) => {
diff --git a/detox/src/utils/exec.js b/detox/src/utils/exec.js
index 9b086bba8..d73dc54ef 100644
--- a/detox/src/utils/exec.js
+++ b/detox/src/utils/exec.js
@@ -124,15 +124,14 @@ function _composeCommand(bin, prefix, args) {
 }
 
 function spawnAndLog(command, flags, options) {
-  const trackingId = _operationCounter++;
   const cmd = _joinCommandAndFlags(command, flags);
-  const log = execLogger.child({ fn: 'spawnAndLog', cmd, trackingId });
 
   const result = spawn(command, flags, {stdio: ['ignore', 'pipe', 'pipe'], ...options});
   const { childProcess } = result;
   const { exitCode, stdout, stderr } = childProcess;
 
-  log.debug({ event: 'SPAWN_CMD' }, `[pid=${childProcess.pid}] ${cmd}`);
+  const log = execLogger.child({ cmd, trackingId: childProcess.pid });
+  log.debug({ event: 'SPAWN_CMD' }, `${cmd}`);
 
   if (exitCode != null && exitCode !== 0) {
     log.error({ event: 'SPAWN_ERROR' }, `${cmd} failed with code = ${exitCode}`);
@@ -147,7 +146,7 @@ function spawnAndLog(command, flags, options) {
     const signal = e.childProcess.signalCode || '';
     const action = signal ? `terminated with ${signal}` : `finished with code = ${e.code}`;
 
-    log.trace({ event: 'SPAWN_END' }, `${cmd} ${action}`);
+    log.debug({ event: 'SPAWN_END' }, `${cmd} ${action}`);
   }
 
   result.then(onEnd, onEnd);
@@ -164,22 +163,33 @@ function _joinCommandAndFlags(command, flags) {
   return result;
 }
 
-async function interruptProcess(childProcessPromise, signal = 'SIGINT') {
-  const log = execLogger.child({ fn: 'interruptProcess' });
+const DEFAULT_KILL_SCHEDULE = {
+  SIGINT: 0,
+};
 
+async function interruptProcess(childProcessPromise, schedule) {
   const childProcess = childProcessPromise.childProcess;
   const pid = childProcess.pid;
   const spawnargs = childProcess.spawnargs.join(' ');
+  const log = execLogger.child({ event: 'SPAWN_KILL', trackingId: pid });
 
-  log.debug({ event: 'EXEC_KILL', signal, process_pid: pid }, `sending ${signal} to [pid = ${pid}]: ${spawnargs}`);
-
-  childProcess.kill(signal);
-  await childProcessPromise.catch(e => {
-    /* istanbul ignore if */
-    if (e.exitCode != null) {
-      throw e;
-    }
+  const handles = _.mapValues({ ...DEFAULT_KILL_SCHEDULE, ...schedule }, (ms, signal) => {
+    return setTimeout(() => {
+      log.trace({ signal }, `sending ${signal} to: ${spawnargs}`);
+      childProcess.kill(signal);
+    }, ms);
   });
+
+  try {
+    await childProcessPromise.catch(e => {
+      /* istanbul ignore if */
+      if (e.exitCode != null) {
+        throw e;
+      }
+    });
+  } finally {
+    _.forEach(handles, handle => clearTimeout(handle));
+  }
 }
 
 async function execAsync(command) {


Test patch:
diff --git a/detox/src/utils/exec.interruptProcess.test.js b/detox/src/utils/exec.interruptProcess.test.js
index 7c5ee1a5e..53f7acabb 100644
--- a/detox/src/utils/exec.interruptProcess.test.js
+++ b/detox/src/utils/exec.interruptProcess.test.js
@@ -2,7 +2,7 @@ jest.mock('./logger');
 
 const { interruptProcess, spawnAndLog } = require('./exec');
 
-describe(interruptProcess.name, () => {
+describe('interruptProcess', () => {
   it('should interrupt a child process promise', async () => {
     await interruptProcess(spawnAndLog('sleep', ['3']));
   }, 500);
@@ -14,4 +14,15 @@ describe(interruptProcess.name, () => {
 
     await interruptProcess(spawnAndLog('node', ['-e', script]));
   }, 1000);
+
+  it('should SIGTERM a stuck process after specified time', async () => {
+    const script =
+      "process.on('SIGINT', () => {});" +
+      "setTimeout(()=>process.exit(1), 10000);";
+
+    const theProcess = spawnAndLog('node', ['-e', script]);
+    await interruptProcess(theProcess, {
+      SIGTERM: 500
+    });
+  }, 1000);
 });
diff --git a/detox/src/utils/exec.test.js b/detox/src/utils/exec.test.js
index 292f82556..74ee16a34 100644
--- a/detox/src/utils/exec.test.js
+++ b/detox/src/utils/exec.test.js
@@ -254,21 +254,23 @@ describe('spawn', () => {
   });
 
   it('should collect output and log it', async () => {
+    jest.spyOn(log, 'child');
     await exec.spawnAndLog('command', []);
     await nextCycle();
 
-    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), '[pid=2018] command');
-    expect(log.trace).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_END' }), 'command finished with code = 0');
-    expect(log.trace).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_STDOUT', stdout: true }), 'hello');
-    expect(log.error).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_STDERR', stderr: true }), 'world');
+    expect(log.child).toHaveBeenCalledWith(expect.objectContaining({ trackingId: 2018 }));
+    expect(log.debug).toHaveBeenCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), 'command');
+    expect(log.debug).toHaveBeenCalledWith(expect.objectContaining({ event: 'SPAWN_END' }), 'command finished with code = 0');
+    expect(log.trace).toHaveBeenCalledWith(expect.objectContaining({ event: 'SPAWN_STDOUT' }), 'hello');
+    expect(log.error).toHaveBeenCalledWith(expect.objectContaining({ event: 'SPAWN_STDERR' }), 'world');
   });
 
   it('should not log output if silent: true', async () => {
     await exec.spawnAndLog('command', [], { silent: true });
     await nextCycle();
 
-    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), '[pid=2018] command');
-    expect(log.trace).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_END' }), 'command finished with code = 0');
+    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), 'command');
+    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_END' }), 'command finished with code = 0');
     expect(log.trace).not.toBeCalledWith(expect.objectContaining({ event: 'SPAWN_STDOUT', stdout: true }), expect.any(String));
     expect(log.error).not.toBeCalledWith(expect.objectContaining({ event: 'SPAWN_STDERR', stderr: true }), expect.any(String));
   });
@@ -287,8 +289,8 @@ describe('spawn', () => {
     await exec.spawnAndLog('command', []).catch(() => {});
     await nextCycle();
 
-    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), '[pid=8102] command');
-    expect(log.trace).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_END' }), 'command finished with code = -2');
+    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), 'command');
+    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_END' }), 'command finished with code = -2');
     expect(log.error).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_STDERR', stderr: true }), 'Some error.');
   });
 
@@ -307,7 +309,7 @@ describe('spawn', () => {
     await exec.spawnAndLog('command', []);
     await nextCycle();
 
-    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), '[pid=null] command');
+    expect(log.debug).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_CMD' }), 'command');
     expect(log.error).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_ERROR' }), 'command failed with code = -2');
     expect(log.error).toBeCalledWith(expect.objectContaining({ event: 'SPAWN_STDERR', stderr: true }), 'Command `command` not found.');
   });