Repository: wix/Detox
Pull request #2125 (2020-06-13 14:32:52)

fix(jest-circus): improved timeout errors inside handleTestEvent()
- [x] This is a small change

---

**Description:**

1. Not all potential timeout places in `handleTestEvent` would print an error in the implementation of #2009.

2. The timeout duration calculation was incorrect and oversimplified. Now, handleTestEvent cannot last for more than `state.testTimeout` ms, or `this.initTimeout + state.testTimeout` ms (only in the case of `setup` phase).

This way the new DetoxCircusEnvironment will be able to print more meaningful errors in emergency situations.

**Examples:**

1. Immediate Detox error.

![Screenshot from 2020-06-13 17-31-00](https://user-images.githubusercontent.com/1962469/84571432-be273c80-ad9b-11ea-921b-36abad3fdf90.png)

2. Timeout error + internal error.

![Screenshot from 2020-06-13 17-30-38](https://user-images.githubusercontent.com/1962469/84571438-c54e4a80-ad9b-11ea-9739-55daaccd399d.png)

**Comparison with the original #2009**

1.

![Screenshot from 2020-06-13 17-33-28](https://user-images.githubusercontent.com/1962469/84571476-06465f00-ad9c-11ea-94f7-28dd49462c1d.png)

2.

![Screenshot from 2020-06-13 17-34-25](https://user-images.githubusercontent.com/1962469/84571499-2d9d2c00-ad9c-11ea-8765-6170436a089b.png)



Patch:
diff --git a/detox/runners/jest-circus/environment.js b/detox/runners/jest-circus/environment.js
index d8e08de6b..8daa0840f 100644
--- a/detox/runners/jest-circus/environment.js
+++ b/detox/runners/jest-circus/environment.js
@@ -4,7 +4,15 @@ const DetoxCoreListener = require('./listeners/DetoxCoreListener');
 const DetoxInitErrorListener = require('./listeners/DetoxInitErrorListener');
 const assertJestCircus26 = require('./utils/assertJestCircus26');
 const wrapErrorWithNoopLifecycle = require('./utils/wrapErrorWithNoopLifecycle');
-const timely = require('../../src/utils/timely');
+const Timer = require('../../src/utils/Timer');
+
+const SYNC_CIRCUS_EVENTS = new Set([
+  'start_describe_definition',
+  'finish_describe_definition',
+  'add_hook',
+  'add_test',
+  'error',
+]);
 
 /**
  * @see https://www.npmjs.com/package/jest-circus#overview
@@ -13,13 +21,13 @@ class DetoxCircusEnvironment extends NodeEnvironment {
   constructor(config) {
     super(assertJestCircus26(config));
 
+    /** @private */
+    this._timer = null;
     /** @private */
     this._listenerFactories = {
       DetoxInitErrorListener,
       DetoxCoreListener,
     };
-    /** @private */
-    this._hookTimeout = undefined;
     /** @protected */
     this.testEventListeners = [];
     /** @protected */
@@ -27,49 +35,80 @@ class DetoxCircusEnvironment extends NodeEnvironment {
   }
 
   get detox() {
-    return require('../../src')._setGlobal(this.global);
+    return require('../../src')
+      ._setGlobal(this.global)
+      ._suppressLoggingInitErrors();
   }
 
   async handleTestEvent(event, state) {
     const { name } = event;
 
-    if (name === 'setup') {
-      await this._onSetup(state);
+    if (SYNC_CIRCUS_EVENTS.has(name)) {
+      return this._handleTestEventSync(event, state);
     }
 
-    await this._timely(async () => {
+    this._timer = new Timer({
+      description: `handling jest-circus "${name}" event`,
+      timeout: name === 'setup' ? this.initTimeout : state.testTimeout,
+    });
+
+    try {
+      if (name === 'setup') {
+        await this._onSetup(state);
+      }
+
       for (const listener of this.testEventListeners) {
         if (typeof listener[name] === 'function') {
-          await listener[name](event, state);
+          try {
+            await this._timer.run(() => listener[name](event, state));
+          } catch (listenerError) {
+            this._logger.error(`${listenerError}`);
+          }
         }
       }
-    });
 
-    if (name === 'teardown') {
-      await this._onTeardown();
+      if (name === 'teardown') {
+        await this._onTeardown(state);
+      }
+    } finally {
+      this._timer.dispose();
+      this._timer = null;
     }
   }
 
-  _timely(fn) {
-    const ms = this._hookTimeout === undefined ? this.initTimeout : this._hookTimeout;
-    return timely(fn, ms, () => {
-      return new Error(`Exceeded timeout of ${ms}ms.`);
-    })();
+  _handleTestEventSync(event, state) {
+    const { name } = event;
+
+    for (const listener of this.testEventListeners) {
+      if (typeof listener[name] === 'function') {
+        listener[name](event, state);
+      }
+    }
   }
 
   async _onSetup(state) {
-    let detox = null;
+    let detox;
 
     try {
-      try {
-        detox = await this._timely(() => this.initDetox());
-      } finally {
-        this._hookTimeout = state.testTimeout;
+      detox = await this._timer.run(async () => {
+        try {
+          return await this.initDetox();
+        } catch (actualError) {
+          state.unhandledErrors.push(actualError);
+          this._logger.error(`${actualError}`);
+          throw actualError;
+        }
+      });
+    } catch (maybeActualError) {
+      if (!state.unhandledErrors.includes(maybeActualError)) {
+        const timeoutError = maybeActualError;
+        state.unhandledErrors.push(timeoutError);
+        this._logger.error(`${timeoutError}`);
       }
-    } catch (initError) {
-      state.unhandledErrors.push(initError);
-      detox = wrapErrorWithNoopLifecycle(initError);
-      await this._onTeardown();
+
+      detox = wrapErrorWithNoopLifecycle(maybeActualError);
+    } finally {
+      this._timer.reset(state.testTimeout);
     }
 
     this._instantiateListeners(detox);
@@ -84,14 +123,20 @@ class DetoxCircusEnvironment extends NodeEnvironment {
     }
   }
 
-  async _onTeardown() {
+  async _onTeardown(state) {
     try {
-      await this._timely(() => this.cleanupDetox());
+      await this._timer.run(() => this.cleanupDetox());
     } catch (cleanupError) {
       state.unhandledErrors.push(cleanupError);
+      this._logger.error(`${cleanupError}`);
     }
   }
 
+  /** @private */
+  get _logger() {
+    return require('../../src/utils/logger');
+  }
+
   /** @protected */
   async initDetox() {
     return this.detox.init();
diff --git a/detox/runners/jest-circus/utils/wrapErrorWithNoopLifecycle.js b/detox/runners/jest-circus/utils/wrapErrorWithNoopLifecycle.js
index 9e0b35b53..9f5ffef50 100644
--- a/detox/runners/jest-circus/utils/wrapErrorWithNoopLifecycle.js
+++ b/detox/runners/jest-circus/utils/wrapErrorWithNoopLifecycle.js
@@ -1,13 +1,13 @@
 const _ = require('lodash');
 const lifecycleSymbols = require('../../integration').lifecycle;
 
-function wrapErrorWithNoopLifecycle(rawError) {
-  const error = _.isError(rawError) ? rawError : new Error(rawError);
+function wrapErrorWithNoopLifecycle(error) {
+  const wrapper = { error };
   for (const symbol of Object.values(lifecycleSymbols)) {
-    error[symbol] = _.noop;
+    wrapper[symbol] = _.noop;
   }
 
-  return error;
+  return wrapper;
 }
 
 module.exports = wrapErrorWithNoopLifecycle;
diff --git a/detox/src/DetoxExportWrapper.js b/detox/src/DetoxExportWrapper.js
index 9c84340b8..6c4fd30b1 100644
--- a/detox/src/DetoxExportWrapper.js
+++ b/detox/src/DetoxExportWrapper.js
@@ -6,10 +6,12 @@ const configuration = require('./configuration');
 const log = require('./utils/logger').child({ __filename });
 
 const _detox = Symbol('detox');
+const _shouldLogInitError = Symbol('shouldLogInitError');
 
 class DetoxExportWrapper {
   constructor() {
     this[_detox] = Detox.none;
+    this[_shouldLogInitError] = true;
 
     this.init = this.init.bind(this);
     this.cleanup = this.cleanup.bind(this);
@@ -61,7 +63,9 @@ class DetoxExportWrapper {
 
       return this[_detox];
     } catch (err) {
-      log.error({ event: 'DETOX_INIT_ERROR' }, '\n', err);
+      if (this[_shouldLogInitError]) {
+        log.error({ event: 'DETOX_INIT_ERROR' }, '\n', err);
+      }
 
       Detox.none.setError(err);
       throw err;
@@ -92,6 +96,12 @@ class DetoxExportWrapper {
     Detox.global = global;
     return this;
   }
+
+  /** @internal */
+  _suppressLoggingInitErrors() {
+    this[_shouldLogInitError] = false;
+    return this;
+  }
 }
 
 module.exports = DetoxExportWrapper;
diff --git a/detox/src/utils/Timer.js b/detox/src/utils/Timer.js
new file mode 100644
index 000000000..d0ec322a6
--- /dev/null
+++ b/detox/src/utils/Timer.js
@@ -0,0 +1,53 @@
+const Deferred = require('./Deferred');
+
+class Timer {
+  /**
+   * @param {string} description - gives more context for thrown errors
+   * @param {number} timeout - maximal allowed duration in milliseconds
+   */
+  constructor({ description, timeout }) {
+    /** @private */
+    this._timeout = timeout;
+    /** @public */
+    this.description = description;
+
+    this._schedule();
+  }
+
+  _schedule() {
+    this._createdAt = Date.now();
+    this._timeoutDeferred = new Deferred();
+    this._timeoutHandle = setTimeout(() => {
+      this._timeoutDeferred.resolve();
+    }, this._timeout);
+  }
+
+  async run(action) {
+    const error = new Error();
+
+    return Promise.race([
+      this._timeoutDeferred.promise.then(() => {
+        error.message = `Exceeded timeout of ${this._timeout}ms while ${this.description}`;
+        throw error;
+      }),
+      Promise.resolve().then(action),
+    ]);
+  }
+
+  dispose() {
+    clearTimeout(this._timeoutHandle);
+  }
+
+  reset(extraDelayMs) {
+    this._timeout = extraDelayMs;
+
+    if (this._timeoutDeferred.status !== Deferred.PENDING) {
+      this._schedule();
+    } else {
+      clearTimeout(this._timeoutHandle);
+      this._timeoutHandle = setTimeout(() => this._timeoutDeferred.resolve(), extraDelayMs);
+    }
+  }
+}
+
+module.exports = Timer;
diff --git a/detox/src/utils/timely.js b/detox/src/utils/timely.js
deleted file mode 100644
index ecc60a698..000000000
--- a/detox/src/utils/timely.js
+++ /dev/null
@@ -1,20 +0,0 @@
-const isPromise = require('./isPromise');
-
-function timely(fn, ms, createRejectReason) {
-  return function () {
-    return new Promise((resolve, reject) => {
-      const maybePromise = fn(...arguments);
-      if (!isPromise(maybePromise)) {
-        return resolve(maybePromise);
-      }
-
-      const promise = maybePromise;
-      const rejectReason = createRejectReason();
-      const handle = setTimeout(reject, ms, rejectReason);
-      promise.finally(() => clearTimeout(handle));
-      promise.then(resolve, reject);
-    });
-  };
-}
-
-module.exports = timely;


Test patch:
diff --git a/detox/src/index.test.js b/detox/src/index.test.js
index aff2a3078..e3108f225 100644
--- a/detox/src/index.test.js
+++ b/detox/src/index.test.js
@@ -35,8 +35,7 @@ describe('index (regular)', () => {
 
     const MissingDetox = require('./utils/MissingDetox');
     Detox.none = new MissingDetox();
-    detox = require('./index');
-    detox._setGlobal(global);
+    detox = require('./index')._setGlobal(global);
     detoxInstance = null;
   });
 
@@ -124,6 +123,21 @@ describe('index (regular)', () => {
       });
     });
 
+    describe('when detox.init() throws with _suppressLoggingInitErrors() configuration', () => {
+      beforeEach(async () => {
+        configuration.composeDetoxConfig.mockImplementation(async () => {
+          throw new Error('Configuration test error');
+        });
+
+        detox._suppressLoggingInitErrors();
+        await detox.init().catch(() => {});
+      });
+
+      it(`should not log init errors with the logger`, async () => {
+        expect(logger.error).not.toHaveBeenCalled();
+      });
+    });
+
     describe('when behaviorConfig.init.exposeGlobals = true', () => {
       beforeEach(async () => {
         detoxConfig.behaviorConfig.init.exposeGlobals = true;
diff --git a/detox/src/utils/Timer.test.js b/detox/src/utils/Timer.test.js
new file mode 100644
index 000000000..b18fb2200
--- /dev/null
+++ b/detox/src/utils/Timer.test.js
@@ -0,0 +1,90 @@
+jest.useFakeTimers('modern');
+
+describe('Timer', () => {
+  let Timer;
+
+  beforeEach(() => {
+    Timer = require('./Timer');
+  });
+
+  it('should run action in time', async () => {
+    const timer = new Timer({
+      description: 'running test',
+      timeout: 1000,
+    });
+
+    expect(await timer.run(() => 5)).toBe(5);
+  });
+
+  it('should throw if an action takes longer', async () => {
+    const timer = new Timer({
+      description: 'running this test',
+      timeout: 999,
+    });
+
+    jest.advanceTimersByTime(1000);
+    await expect(timer.run(() => {}))
+      .rejects.toThrowError(/Exceeded timeout of 999ms while running this test/);
+  });
+
+  it('should throw if a sequence of actions takes longer', async () => {
+    const timer = new Timer({
+      description: 'running this test',
+      timeout: 999,
+    });
+
+    for (let i = 0; i < 10; i++) {
+      await timer.run(() => {});
+      jest.advanceTimersByTime(100);
+    }
+
+    await expect(timer.run(() => {}))
+      .rejects.toThrowError(/Exceeded timeout of 999ms while running this test/);
+  });
+
+  it('should be disposable', async () => {
+    const timer = new Timer({
+      description: 'running this test',
+      timeout: 999,
+    });
+
+    timer.dispose();
+    jest.advanceTimersByTime(2000);
+    await expect(timer.run(() => 5)).resolves.toBe(5);
+  });
+
+  it('should reset timer while it is running', async () => {
+    const timer = new Timer({
+      description: 'running this test',
+      timeout: 500,
+    });
+
+    jest.advanceTimersByTime(499);
+    timer.reset(100);
+
+    jest.advanceTimersByTime(99);
+
+    await expect(timer.run(() => 5)).resolves.toBe(5);
+    jest.advanceTimersByTime(1);
+    await expect(timer.run(() => 5))
+      .rejects.toThrowError(/Exceeded timeout of 100ms while running this test/);
+  });
+
+  it('should reset timer after timeout', async () => {
+    const timer = new Timer({
+      description: 'running this test',
+      timeout: 500,
+    });
+
+    jest.advanceTimersByTime(500);
+    await expect(timer.run(() => 5))
+      .rejects.toThrowError(/Exceeded timeout of 500ms while running this test/);
+
+    timer.reset(100);
+    await expect(timer.run(() => 5)).resolves.toBe(5);
+
+    jest.advanceTimersByTime(100);
+    await expect(timer.run(() => 5))
+      .rejects.toThrowError(/Exceeded timeout of 100ms while running this test/);
+  });
+});
diff --git a/detox/src/utils/timely.test.js b/detox/src/utils/timely.test.js
deleted file mode 100644
index c8baef5a0..000000000
--- a/detox/src/utils/timely.test.js
+++ /dev/null
@@ -1,23 +0,0 @@
-const timely = require('./timely');
-
-describe('timely', () => {
-  it('should wrap async functions with a timeout error (happy path)', async () => {
-    const fortyTwo = async () => 42;
-    const fortyTwoTimed = timely(fortyTwo, 1000, () => new Error());
-
-    await expect(fortyTwoTimed()).resolves.toBe(42);
-  });
-
-  it('should wrap async functions with a timeout error (unhappy path)', async () => {
-    const infinitely = () => new Promise(() => {});
-    const infinitelyTimed = timely(infinitely, 0, () => new Error('No One Lives Forever'));
-
-    await expect(infinitelyTimed()).rejects.toThrow('No One Lives Forever');
-  });
-
-  it('should wrap sync functions as a fallback too', async () => {
-    const syncTimely = timely(() => 42, 1000, () => new Error());
-
-    await expect(syncTimely()).resolves.toBe(42);
-  });
-});
diff --git a/detox/test/e2e/environment.js b/detox/test/e2e/environment.js
index 3163b6494..363ba9a41 100644
--- a/detox/test/e2e/environment.js
+++ b/detox/test/e2e/environment.js
@@ -26,8 +26,7 @@ class CustomDetoxEnvironment extends DetoxCircusEnvironment {
 
   async _initDetoxWithHangingServer() {
     console.log('Making problems with server');
-    const config = require('../package.json').detox;
-    const instance = await this.detox.init(config, { launchApp: false });
+    const instance = await this.detox.init(undefined, { launchApp: false });
     const sendActionOriginal = instance._server.sendAction;
     instance._server.sendAction = function(ws, action) {
       if (action.type !== 'ready') {