Repository: wix/Detox
Pull request #2326 (2020-09-11 07:52:59)

fix(jest): improve error printing for Node 10.x
- [x] This change has been discussed in issue #2312 and the solution has been agreed upon with maintainers.

---

**Description:**

- [x] fix the issue
- [x] develop unhappy e2e suite


Patch:
diff --git a/detox/src/client/Client.js b/detox/src/client/Client.js
index 3628d70bd..9e2e8db8f 100644
--- a/detox/src/client/Client.js
+++ b/detox/src/client/Client.js
@@ -3,7 +3,7 @@ const AsyncWebSocket = require('./AsyncWebSocket');
 const actions = require('./actions/actions');
 const argparse = require('../utils/argparse');
 const log = require('../utils/logger').child({ __filename });
-const { asError, removeInternalStackEntries } = require('../utils/errorUtils');
+const { asError, createErrorWithUserStack, replaceErrorStack } = require('../utils/errorUtils');
 
 class Client {
   constructor(config) {
@@ -94,6 +94,8 @@ class Client {
   }
 
   async execute(invocation) {
+    const errorWithUserStack = createErrorWithUserStack();
+
     if (typeof invocation === 'function') {
       invocation = invocation();
     }
@@ -102,7 +104,7 @@ class Client {
       return await this.sendAction(new actions.Invoke(invocation));
     } catch (err) {
       this.successfulTestRun = false;
-      throw removeInternalStackEntries(asError(err));
+      throw replaceErrorStack(errorWithUserStack, asError(err));
     }
   }
 
@@ -138,8 +140,6 @@ class Client {
     let handledResponse;
     try {
       handledResponse = await action.handle(parsedResponse);
-    } catch (ex) {
-      throw ex;
     } finally {
       clearTimeout(this.slowInvocationStatusHandler);
     }
diff --git a/detox/src/utils/errorUtils.js b/detox/src/utils/errorUtils.js
index 9c4af0711..654ce3789 100644
--- a/detox/src/utils/errorUtils.js
+++ b/detox/src/utils/errorUtils.js
@@ -1,20 +1,36 @@
 const { isError } = require('lodash');
+const CLEAN_AT = /\n\s*at [\s\S]*/m;
 
-function removeInternalStackEntries(error) {
-  const lines = error.stack.split('\n');
+function filterErrorStack(error, predicate) {
+  const stackLines = (error.stack || '').split('\n');
+  const resultLines = [];
+  for (const line of stackLines) {
+    if (line.trimLeft().startsWith('at') && !predicate(line)) {
+      continue;
+    }
 
-  const filtered = lines.filter(rawLine => {
-    const line = rawLine.trim();
+    resultLines.push(line);
+  }
+  error.stack = resultLines.join('\n');
+  return error;
+}
 
-    if (line.startsWith('at ') && line.includes('/detox/src')) {
-      return false;
-    }
+function replaceErrorStack(source, target) {
+  const sourceStack = source.stack || source.message;
+  const targetStack = target.stack || target.message;
+  const sourceMessage = sourceStack.replace(CLEAN_AT, '');
+  const targetMessage = targetStack.replace(CLEAN_AT, '');
+  const actualSourceStack = sourceStack.slice(sourceMessage.length);
+  target.stack = targetMessage + actualSourceStack;
+  return target;
+}
 
-    return true;
-  });
+function isInternalStackLine(line) {
+  return line.indexOf('/detox/src/') === -1;
+}
 
-  error.stack = filtered.join('\n');
-  return error;
+function createErrorWithUserStack() {
+  return filterErrorStack(new Error(), isInternalStackLine);
 }
 
 function asError(error) {
@@ -22,6 +38,8 @@ function asError(error) {
 }
 
 module.exports = {
-  removeInternalStackEntries,
   asError,
+  replaceErrorStack,
+  filterErrorStack,
+  createErrorWithUserStack,
 };
diff --git a/scripts/ci.android.sh b/scripts/ci.android.sh
index 23cc74ab2..c935b98e0 100755
--- a/scripts/ci.android.sh
+++ b/scripts/ci.android.sh
@@ -23,11 +23,7 @@ cp ../coverage/lcov.info ../../coverage/unit.lcov
 run_f "npm run e2e:android-ci"
 cp coverage/lcov.info ../../coverage/e2e-android-ci.lcov
 
-run_f "npm run e2e:android-timeout-ci"
-cp coverage/lcov.info ../../coverage/e2e-android-timeout-ci.lcov
-
-run_f "npm run e2e:legacy-jasmine:android-timeout-ci"
-cp coverage/lcov.info ../../coverage/e2e-legacy-jasmine-android-timeout-ci.lcov
+run_f "scripts/ci_unhappy.sh android"
 
 # run_f "npm run verify-artifacts:android"
 popd
diff --git a/scripts/ci.ios.sh b/scripts/ci.ios.sh
index 824822dfe..019e91f8b 100755
--- a/scripts/ci.ios.sh
+++ b/scripts/ci.ios.sh
@@ -14,11 +14,7 @@ cp ../coverage/lcov.info ../../coverage/unit.lcov
 run_f "npm run e2e:ios-ci"
 cp coverage/lcov.info ../../coverage/e2e-ios-ci.lcov
 
-run_f "npm run e2e:ios-timeout-ci"
-cp coverage/lcov.info ../../coverage/e2e-ios-timeout-ci.lcov
-
-run_f "npm run e2e:legacy-jasmine:ios-timeout-ci"
-cp coverage/lcov.info ../../coverage/e2e-legacy-jasmine-ios-timeout-ci.lcov
+run_f "scripts/ci_unhappy.sh ios"
 
 # run_f "npm run verify-artifacts:ios"
 popd


Test patch:
diff --git a/detox/src/utils/errorUtils.test.js b/detox/src/utils/errorUtils.test.js
index 305d37aad..c7cf8b3d8 100644
--- a/detox/src/utils/errorUtils.test.js
+++ b/detox/src/utils/errorUtils.test.js
@@ -1,40 +1,73 @@
-const { asError, removeInternalStackEntries } = require('./errorUtils');
-
-describe('removeInternalStackEntries', () => {
-  let error;
-
-  beforeEach(() => {
-    error = new Error('This is a test error\non multiple lines.');
-    error.stack = `Error: This is a test error
-on multiple lines.
-    at Object.<anonymous> (/home/noomorph/Projects/wix/Detox/detox/src/utils/errorUtils.test.js:19:12)
-    at Object.asyncJestTest (/home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:100:37)
-    at /home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/queueRunner.js:47:12
-    at new Promise (<anonymous>)
-    at mapper (/home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/queueRunner.js:30:19)
-    at /home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/queueRunner.js:77:41
-    at processTicksAndRejections (internal/process/task_queues.js:97:5)`;
+const _ = require("lodash");
+const errorUtils = require("./errorUtils");
+
+describe('sliceErrorStack(error, fromIndex)', () => {
+  it('should clean up error stack by N first lines containing at:', () => {
+    function innerFunction() { throw new Error('Source Error'); }
+    function outerFunction() { innerFunction(); }
+    const slicer = at => (_line) => --at < 0;
+    const error0 = errorUtils.filterErrorStack(_.attempt(outerFunction), slicer(0));
+    const error2 = errorUtils.filterErrorStack(_.attempt(outerFunction), slicer(1));
+    const error3 = errorUtils.filterErrorStack(_.attempt(outerFunction), slicer(2));
+    expect(error0.stack).toMatch(/at innerFunction/);
+    expect(error0.stack).toMatch(/at outerFunction/);
+    expect(error2.stack).not.toMatch(/at innerFunction/);
+    expect(error2.stack).toMatch(/at outerFunction/);
+    expect(error3.stack).not.toMatch(/at innerFunction/);
+    expect(error3.stack).not.toMatch(/at outerFunction/);
+  });
+
+  it('should not fail if an error stack is empty', () => {
+    const err = new Error();
+    delete err.stack;
+
+    errorUtils.filterErrorStack(err, () => true)
+    expect(err.stack).toBe('');
   });
+});
+
+describe('replaceErrorStack(source, target)', () => {
+  it('should replace error stack in the target error using the source error', () => {
+    function sourceFunction() { throw new Error('Source Error'); }
+    function targetFunction() { throw new Error('Target Error'); }
+    const source = _.attempt(sourceFunction);
+    const target = _.attempt(targetFunction);
+    expect(target.stack).toMatch(/Target Error/);
+    expect(target.stack).toMatch(/at targetFunction/);
+    expect(target.stack).not.toMatch(/at sourceFunction/);
+    expect(errorUtils.replaceErrorStack(source, target)).toBe(target);
+    expect(target.stack).toMatch(/Target Error/);
+    expect(target.stack).toMatch(/at sourceFunction/);
+    expect(target.stack).not.toMatch(/at targetFunction/);
+  });
+
+  it('should not ruin already malformed errors', () => {
+    const err1 = new Error('Source');
+    const err2 = new Error('Target');
+    delete err1.stack;
+    delete err2.stack;
+
+    errorUtils.replaceErrorStack(err1, err2);
+    expect(err2.stack).toBe('Target');
+  });
+});
 
-  it('should include regular stack lines and omit detox/src stack lines', () => {
-    expect(removeInternalStackEntries(error).stack).toBe(`Error: This is a test error
-on multiple lines.
-    at Object.asyncJestTest (/home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:100:37)
-    at /home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/queueRunner.js:47:12
-    at new Promise (<anonymous>)
-    at mapper (/home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/queueRunner.js:30:19)
-    at /home/noomorph/Projects/wix/Detox/detox/node_modules/jest-jasmine2/build/queueRunner.js:77:41
-    at processTicksAndRejections (internal/process/task_queues.js:97:5)`);
+describe('createErrorWithUserStack()', () => {
+  it('should not have /detox/src/ lines in stack', () => {
+    expect(new Error().stack).toContain('/detox/src/'); // sanity assertion
+    expect(errorUtils.createErrorWithUserStack()).not.toContain('/detox/src/');
   });
 });
 
-describe('asError', () => {
-  it('should pass through errors', () => {
-    const e = new Error();
-    expect(asError(e)).toBe(e);
+describe('asError(err)', () => {
+  it('should passthrough Error instances', () => {
+    const err = new Error();
+    expect(errorUtils.asError(err)).toBe(err);
   });
 
-  it('should wrap non-errors with new Error()', () => {
-    expect(asError(42)).toEqual(new Error('42'));
+  it('should wrap non-Error with Error', () => {
+    const err = 'non-Error'
+    expect(errorUtils.asError(err)).toBeInstanceOf(Error);
+    expect(errorUtils.asError(err).message).toBe(err);
   });
 });
diff --git a/detox/test/e2e-unhappy/detox-init-timeout/jest-circus/config.js b/detox/test/e2e-unhappy/detox-init-timeout/jest-circus/config.js
new file mode 100644
index 000000000..c36dca787
--- /dev/null
+++ b/detox/test/e2e-unhappy/detox-init-timeout/jest-circus/config.js
@@ -0,0 +1,13 @@
+const path = require('path').posix;
+
+const rootDir =  '../../../..';
+const dirname = './' + path.relative(path.join(__dirname, rootDir), __dirname);
+
+module.exports = {
+  ...require(`${rootDir}/test/e2e/config.js`),
+
+  rootDir,
+
+  testEnvironment: `${dirname}/environment.js`,
+  testMatch: ["**/detox-init-timeout/timeout.test.js"],
+};
diff --git a/detox/test/e2e-unhappy/detox-init-timeout/jest-circus/environment.js b/detox/test/e2e-unhappy/detox-init-timeout/jest-circus/environment.js
new file mode 100644
index 000000000..eba414a87
--- /dev/null
+++ b/detox/test/e2e-unhappy/detox-init-timeout/jest-circus/environment.js
@@ -0,0 +1,32 @@
+const WorkerAssignReporterCircus = require('detox/runners/jest/WorkerAssignReporterCircus');
+const SpecReporterCircus = require('detox/runners/jest/SpecReporterCircus');
+const DetoxCircusEnvironment = require('detox/runners/jest-circus/environment');
+
+class CustomDetoxEnvironment extends DetoxCircusEnvironment {
+  constructor(config) {
+    super(config);
+
+    this.initTimeout = 30000;
+    this.registerListeners({
+      SpecReporterCircus,
+      WorkerAssignReporterCircus,
+    });
+  }
+
+  async initDetox() {
+    console.log('Making problems with server');
+
+    const instance = await this.detox.init(undefined, { launchApp: false });
+    const sendActionOriginal = instance._server.sendAction;
+    instance._server.sendAction = function(ws, action) {
+      if (action.type !== 'ready') {
+        sendActionOriginal.call(this, ws, action);
+      }
+    };
+
+    await instance.device.launchApp();
+    return instance;
+  }
+}
+
+module.exports = CustomDetoxEnvironment;
diff --git a/detox/test/e2e-unhappy/detox-init-timeout/jest-jasmine/config.js b/detox/test/e2e-unhappy/detox-init-timeout/jest-jasmine/config.js
new file mode 100644
index 000000000..bb690ceac
--- /dev/null
+++ b/detox/test/e2e-unhappy/detox-init-timeout/jest-jasmine/config.js
@@ -0,0 +1,16 @@
+const path = require('path').posix;
+
+const rootDir =  '../../../..';
+const dirname = './' + path.relative(path.join(__dirname, rootDir), __dirname);
+
+module.exports = {
+  ...require(`../../../e2e/config.js`),
+
+  rootDir,
+
+  setupFilesAfterEnv: [`${dirname}/init.js`],
+
+  testRunner: 'jasmine2',
+  testMatch: ["**/detox-init-timeout/timeout.test.js"],
+  testEnvironment: 'node',
+};
diff --git a/detox/test/e2e-unhappy/detox-init-timeout/jest-jasmine/init.js b/detox/test/e2e-unhappy/detox-init-timeout/jest-jasmine/init.js
new file mode 100644
index 000000000..6060d6575
--- /dev/null
+++ b/detox/test/e2e-unhappy/detox-init-timeout/jest-jasmine/init.js
@@ -0,0 +1,43 @@
+const detox = require('detox');
+const adapter = require('detox/runners/jest/adapter');
+const specReporter = require('detox/runners/jest/specReporter');
+const assignReporter = require('detox/runners/jest/assignReporter');
+
+jasmine.getEnv().addReporter(adapter);
+
+// This takes care of generating status logs on a per-spec basis. By default, jest only reports at file-level.
+// This is strictly optional.
+jasmine.getEnv().addReporter(specReporter);
+
+// This will post which device has assigned to run a suite, which can be useful in a multiple-worker tests run.
+// This is strictly optional.
+jasmine.getEnv().addReporter(assignReporter);
+
+beforeAll(async () => {
+  await detox.init();
+}, 30000);
+
+beforeEach(async () => {
+  try {
+    await adapter.beforeEach();
+  } catch (err) {
+    await detox.cleanup();
+    throw err;
+  }
+});
+
+afterAll(async () => {
+  await adapter.afterAll();
+  await detox.cleanup();
+});
+
+// simulate app-is-never-ready state
+
+const DetoxServer = require('detox/src/server/DetoxServer');
+
+const originalFn = DetoxServer.prototype.sendAction;
+DetoxServer.prototype.sendAction = function (ws, action) {
+  if (action.type !== 'ready') {
+    originalFn.call(this, ws, action);
+  }
+};
diff --git a/detox/test/e2e-unhappy/detox-init-timeout/timeout.test.js b/detox/test/e2e-unhappy/detox-init-timeout/timeout.test.js
new file mode 100644
index 000000000..ce9720f25
--- /dev/null
+++ b/detox/test/e2e-unhappy/detox-init-timeout/timeout.test.js
@@ -0,0 +1,1 @@
+it('should fail with timeout', () => {});
diff --git a/detox/test/e2e-unhappy/failing-matcher.test.js b/detox/test/e2e-unhappy/failing-matcher.test.js
new file mode 100644
index 000000000..4d8953656
--- /dev/null
+++ b/detox/test/e2e-unhappy/failing-matcher.test.js
@@ -0,0 +1,5 @@
+describe('Error stack mangling', () => {
+  it('should fail with a correct stack trace', async () => {
+    await element(by.text('supercalifragilisticexpialidocious')).tap();
+  });
+});
diff --git a/detox/test/e2e/25.timeout.test.js b/detox/test/e2e/25.timeout.test.js
deleted file mode 100644
index dc28cf80f..000000000
--- a/detox/test/e2e/25.timeout.test.js
+++ /dev/null
@@ -1,21 +0,0 @@
-const DetoxServer = require('detox/src/server/DetoxServer');
-
-function causeAppNotReady() {
-  const originalFn = DetoxServer.prototype.sendAction;
-
-  DetoxServer.prototype.sendAction = function (ws, action) {
-    if (action.type !== 'ready') {
-      originalFn.call(this, ws, action);
-    }
-  };
-}
-
-if (process.env.TIMEOUT_E2E_TEST === '1') {
-  if (typeof jasmine !== 'undefined') {
-    causeAppNotReady();
-  }
-
-  it('timeout test', () => {});
-} else {
-  it('empty test', () => {});
-}
diff --git a/detox/test/e2e/environment.js b/detox/test/e2e/environment.js
index ad3e2b701..c8051b930 100644
--- a/detox/test/e2e/environment.js
+++ b/detox/test/e2e/environment.js
@@ -6,10 +6,6 @@ class CustomDetoxEnvironment extends DetoxCircusEnvironment {
   constructor(config) {
     super(config);
 
-    if (process.env.TIMEOUT_E2E_TEST) {
-      this.initTimeout = 30000;
-    }
-
     this.registerListeners({
       SpecReporterCircus,
       WorkerAssignReporterCircus,
@@ -17,13 +13,7 @@ class CustomDetoxEnvironment extends DetoxCircusEnvironment {
   }
 
   async initDetox() {
-    let instance;
-
-    if (process.env.TIMEOUT_E2E_TEST) {
-      instance = await this._initDetoxWithHangingServer();
-    } else {
-      instance = await super.initDetox();
-    }
+    const instance = await super.initDetox();
 
     this.global.detox.__waitUntilArtifactsManagerIsIdle__ = () => {
       return instance._artifactsManager._idlePromise;
@@ -31,20 +21,6 @@ class CustomDetoxEnvironment extends DetoxCircusEnvironment {
 
     return instance;
   }
-
-  async _initDetoxWithHangingServer() {
-    console.log('Making problems with server');
-    const instance = await this.detox.init(undefined, { launchApp: false });
-    const sendActionOriginal = instance._server.sendAction;
-    instance._server.sendAction = function(ws, action) {
-      if (action.type !== 'ready') {
-        sendActionOriginal.call(this, ws, action);
-      }
-    };
-
-    await instance.device.launchApp();
-    return instance;
-  }
 }
 
 process.on('unhandledRejection', (reason, p) => {
diff --git a/detox/test/package.json b/detox/test/package.json
index 8be50fdad..270d6cf89 100644
--- a/detox/test/package.json
+++ b/detox/test/package.json
@@ -15,11 +15,7 @@
     "e2e:android": "detox test -c android.emu.release",
     "e2e:android-debug": "detox test -c android.emu.debug",
     "e2e:ios-ci": "npm run e2e:ios -- --workers 3 --retries 1",
-    "e2e:ios-timeout-ci": "node scripts/assert_timeout.js npm run e2e:ios -- e2e/25.timeout.test.js",
     "e2e:android-ci": "npm run e2e:android -- --workers 3 --retries 1 --headless --jest-report-specs --loglevel verbose",
-    "e2e:android-timeout-ci": "node scripts/assert_timeout.js npm run e2e:android -- --headless e2e/25.timeout.test.js",
-    "e2e:legacy-jasmine:ios-timeout-ci": "node scripts/assert_timeout.js npm run e2e:ios -- -o e2e/config-jasmine.js --take-screenshots failing e2e/25.timeout.test.js",
-    "e2e:legacy-jasmine:android-timeout-ci": "node scripts/assert_timeout.js npm run e2e:android -- -o e2e/config-jasmine.js --take-screenshots failing e2e/25.timeout.test.js",
     "build:ios": "detox build -c ios.sim.release",
     "build:android": "detox build -c android.emu.release",
     "build:android-debug": "detox build -c android.emu.debug",
@@ -53,6 +49,7 @@
   "detox": {
     "test-runner": "nyc jest",
     "runner-config": "e2e/config.js",
+    "specs": "e2e/*.test.js",
     "behavior": {
       "init": {
         "reinstallApp": true,
diff --git a/detox/test/scripts/assert_timeout.js b/detox/test/scripts/assert_timeout.js
index e46bca34a..1192fe61b 100644
--- a/detox/test/scripts/assert_timeout.js
+++ b/detox/test/scripts/assert_timeout.js
@@ -3,14 +3,7 @@ const cp = require('child_process');
 
 const [_0, _1, command, ...args] = process.argv;
 
-const testProcess = cp.spawn(command, args, {
-  stdio: 'inherit',
-  env: {
-    ...process.env,
-    TIMEOUT_E2E_TEST: '1',
-    DISABLE_JUNIT_REPORTER: '1',
-  },
-});
+const testProcess = cp.spawn(command, args, { stdio: 'inherit' });
 
 let handle = setTimeout(() => {
   handle = null;
diff --git a/detox/test/scripts/ci_unhappy.sh b/detox/test/scripts/ci_unhappy.sh
new file mode 100755
index 000000000..f31033b56
--- /dev/null
+++ b/detox/test/scripts/ci_unhappy.sh
@@ -0,0 +1,27 @@
+#!/usr/bin/env bash
+
+set -e
+
+export DISABLE_JUNIT_REPORTER=1
+
+platform=$1
+
+echo "Running e2e test for jest-circus timeout handling..."
+node scripts/assert_timeout.js npm run "e2e:$platform" -- -H -o e2e-unhappy/detox-init-timeout/jest-circus/config.js e2e-unhappy 
+cp coverage/lcov.info "../../coverage/e2e-$platform-timeout-ci.lcov"
+
+echo "Running e2e test for jest-jasmine timeout handling..."
+node scripts/assert_timeout.js npm run "e2e:$platform" -- -H -o e2e-unhappy/detox-init-timeout/jest-jasmine/config.js e2e-unhappy 
+cp coverage/lcov.info "../../coverage/e2e-legacy-jasmine-$platform-timeout-ci.lcov"
+
+echo "Running e2e stack trace mangling test..."
+runnerOutput="$(npm run "e2e:$platform" -- -H e2e-unhappy/failing-matcher.test.js 2>&1 | tee /dev/stdout)"
+
+if grep -q "await element.*supercalifragilisticexpialidocious" <<< "$runnerOutput" ;
+then
+    echo "Stack trace mangling has passed OK."
+    cp coverage/lcov.info "../../coverage/e2e-$platform-error-stack-mangling.lcov"
+else
+    echo "Stack trace mangling test has failed"
+    exit 1
+fi