chore(testrunner): distinguish between TERMINATED and CRASHED (#4821)

`testRunner.run()` might have 4 different outcomes:
- `ok` - all non-skipped tests passed
- `failed` - some tests failed or timed out
- `terminated` - process received SIGHUP/SIGINT while testrunner was running tests. This happens on CI's under certain circumstances, e.g. when
  VM is getting re-scheduled.
- `crashed` - testrunner terminated test execution due to either `UnhandledPromiseRejection` or
  some of the hooks (`beforeEach/afterEach/beforeAll/afterAll`) failures.

As an implication, there are 2 new test results: `terminated` and `crashed`.
All possible test results are:
- `ok` - test worked just fine
- `skipped` - test was skipped with `xit`
- `timedout` - test timed out
- `failed` - test threw an exception while running
- `terminated` - testrunner got terminated while running this test
- `crashed` - some `beforeEach` / `afterEach` hook corresponding to this
test timed out of threw an exception.

This patch changes a few parts of the testrunner API:
- `testRunner.run()` now returns an object `{result: string,
terminationError?: Error, terminationMessage?: string}`
- the same object is dispatched via `testRunner.on('finished')` event
- `testRunner.on('terminated')` got removed
- tests now might have `crashed` and `terminated` results
- `testRunner.on('teststarted')` dispatched before running all related
`beforeEach` hooks, and `testRunner.on('testfinished')` dispatched after
running all related `afterEach` hooks.

test/utils.js

@@ -215,7 +215,6 @@ const utils = module.exports = {
         result: test.result,
       });
     });
-    testRunner.on('terminated', () => dashboard.uploadAndCleanup());
     testRunner.on('finished', () => dashboard.uploadAndCleanup());
 
     function generateTestIDs(testRunner) {

utils/testrunner/Reporter.js

@@ -17,6 +17,7 @@
 const RED_COLOR = '\x1b[31m';
 const GREEN_COLOR = '\x1b[32m';
 const YELLOW_COLOR = '\x1b[33m';
+const MAGENTA_COLOR = '\x1b[35m';
 const RESET_COLOR = '\x1b[0m';
 
 class Reporter {
@@ -34,7 +35,6 @@ class Reporter {
     this._summary = summary;
     this._testCounter = 0;
     runner.on('started', this._onStarted.bind(this));
-    runner.on('terminated', this._onTerminated.bind(this));
     runner.on('finished', this._onFinished.bind(this));
     runner.on('teststarted', this._onTestStarted.bind(this));
     runner.on('testfinished', this._onTestFinished.bind(this));
@@ -51,9 +51,8 @@ class Reporter {
       console.log(`Running ${YELLOW_COLOR}${runnableTests.length}${RESET_COLOR} focused tests out of total ${YELLOW_COLOR}${allTests.length}${RESET_COLOR} on ${YELLOW_COLOR}${this._runner.parallel()}${RESET_COLOR} worker(s):\n`);
   }
 
-  _onTerminated(message, error) {
+  _printTermination(result, message, error) {
-    this._printTestResults();
+    console.log(`${RED_COLOR}## ${result.toUpperCase()} ##${RESET_COLOR}`);
-    console.log(`${RED_COLOR}## TERMINATED ##${RESET_COLOR}`);
     console.log('Message:');
     console.log(`  ${RED_COLOR}${message}${RESET_COLOR}`);
     if (error && error.stack) {
@@ -74,8 +73,12 @@ class Reporter {
         description = `${YELLOW_COLOR}SKIPPED${RESET_COLOR}`;
       else if (test.result === 'failed')
         description = `${RED_COLOR}FAILED${RESET_COLOR}`;
+      else if (test.result === 'crashed')
+        description = `${RED_COLOR}CRASHED${RESET_COLOR}`;
       else if (test.result === 'timedout')
         description = `${RED_COLOR}TIMEDOUT${RESET_COLOR}`;
+      else if (test.result === 'terminated')
+        description = `${MAGENTA_COLOR}TERMINATED${RESET_COLOR}`;
       else
         description = `${RED_COLOR}<UNKNOWN>${RESET_COLOR}`;
       console.log(`  ${workerId}: [${description}] ${test.fullName} (${formatTestLocation(test)})`);
@@ -83,10 +86,11 @@ class Reporter {
     process.exitCode = 2;
   }
 
-  _onFinished() {
+  _onFinished({result, terminationError, terminationMessage}) {
     this._printTestResults();
-    const failedTests = this._runner.failedTests();
+    if (terminationMessage || terminationError)
-    process.exitCode = failedTests.length > 0 ? 1 : 0;
+      this._printTermination(result, terminationMessage, terminationError);
+    process.exitCode = result === 'ok' ? 0 : 1;
   }
 
   _printTestResults() {
@@ -102,6 +106,9 @@ class Reporter {
         if (test.result === 'timedout') {
           console.log('  Message:');
           console.log(`    ${RED_COLOR}Timeout Exceeded ${this._runner.timeout()}ms${RESET_COLOR}`);
+        } else if (test.result === 'crashed') {
+          console.log('  Message:');
+          console.log(`    ${RED_COLOR}CRASHED${RESET_COLOR}`);
         } else {
           console.log('  Message:');
           console.log(`    ${RED_COLOR}${test.error.message || test.error}${RESET_COLOR}`);
@@ -189,6 +196,10 @@ class Reporter {
       ++this._testCounter;
       if (test.result === 'ok') {
         console.log(`${this._testCounter}) ${GREEN_COLOR}[ OK ]${RESET_COLOR} ${test.fullName} (${formatTestLocation(test)})`);
+      } else if (test.result === 'terminated') {
+        console.log(`${this._testCounter}) ${MAGENTA_COLOR}[ TERMINATED ]${RESET_COLOR} ${test.fullName} (${formatTestLocation(test)})`);
+      } else if (test.result === 'crashed') {
+        console.log(`${this._testCounter}) ${RED_COLOR}[ CRASHED ]${RESET_COLOR} ${test.fullName} (${formatTestLocation(test)})`);
       } else if (test.result === 'skipped') {
         console.log(`${this._testCounter}) ${YELLOW_COLOR}[SKIP]${RESET_COLOR} ${test.fullName} (${formatTestLocation(test)})`);
       } else if (test.result === 'failed') {
@@ -214,6 +225,10 @@ class Reporter {
         process.stdout.write(`${YELLOW_COLOR}*${RESET_COLOR}`);
       else if (test.result === 'failed')
         process.stdout.write(`${RED_COLOR}F${RESET_COLOR}`);
+      else if (test.result === 'crashed')
+        process.stdout.write(`${RED_COLOR}C${RESET_COLOR}`);
+      else if (test.result === 'terminated')
+        process.stdout.write(`${MAGENTA_COLOR}.${RESET_COLOR}`);
       else if (test.result === 'timedout')
         process.stdout.write(`${RED_COLOR}T${RESET_COLOR}`);
     }

utils/testrunner/TestRunner.js

@@ -97,6 +97,8 @@ const TestResult = {
   Skipped: 'skipped', // User skipped the test
   Failed: 'failed', // Exception happened during running
   TimedOut: 'timedout', // Timeout Exceeded while running
+  Terminated: 'terminated', // Execution terminated
+  Crashed: 'crashed', // If testrunner crashed due to this test
 };
 
 class Test {
@@ -162,10 +164,10 @@ class TestPass {
 
   async run() {
     const terminations = [
-      createTermination.call(this, 'SIGINT', 'SIGINT received'),
+      createTermination.call(this, 'SIGINT', TestResult.Terminated, 'SIGINT received'),
-      createTermination.call(this, 'SIGHUP', 'SIGHUP received'),
+      createTermination.call(this, 'SIGHUP', TestResult.Terminated, 'SIGHUP received'),
-      createTermination.call(this, 'SIGTERM', 'SIGTERM received'),
+      createTermination.call(this, 'SIGTERM', TestResult.Terminated, 'SIGTERM received'),
-      createTermination.call(this, 'unhandledRejection', 'UNHANDLED PROMISE REJECTION'),
+      createTermination.call(this, 'unhandledRejection', TestResult.Crashed, 'UNHANDLED PROMISE REJECTION'),
     ];
     for (const termination of terminations)
       process.on(termination.event, termination.handler);
@@ -179,11 +181,11 @@ class TestPass {
       process.removeListener(termination.event, termination.handler);
     return this._termination;
 
-    function createTermination(event, message) {
+    function createTermination(event, result, message) {
       return {
         event,
         message,
-        handler: error => this._terminate(message, error)
+        handler: error => this._terminate(result, message, error)
       };
     }
   }
@@ -201,11 +203,7 @@ class TestPass {
       if (!this._workerDistribution.hasValue(child, workerId))
         continue;
       if (child instanceof Test) {
-        for (let i = 0; i < suitesStack.length; i++)
+        await this._runTest(workerId, suitesStack, child, state);
-          await this._runHook(workerId, suitesStack[i], 'beforeEach', state, child);
-        await this._runTest(workerId, child, state);
-        for (let i = suitesStack.length - 1; i >= 0; i--)
-          await this._runHook(workerId, suitesStack[i], 'afterEach', state, child);
       } else {
         suitesStack.push(child);
         await this._runSuite(workerId, suitesStack, state);
@@ -215,7 +213,7 @@ class TestPass {
     await this._runHook(workerId, currentSuite, 'afterAll', state);
   }
 
-  async _runTest(workerId, test, state) {
+  async _runTest(workerId, suitesStack, test, state) {
     if (this._termination)
       return;
     this._runner._willStartTest(test, workerId);
@@ -224,47 +222,65 @@ class TestPass {
       this._runner._didFinishTest(test, workerId);
       return;
     }
+    let crashed = false;
+    for (let i = 0; i < suitesStack.length; i++)
+      crashed = (await this._runHook(workerId, suitesStack[i], 'beforeEach', state, test)) || crashed;
+    // If some of the beofreEach hooks error'ed - terminate this test.
+    if (crashed) {
+      test.result = TestResult.Crashed;
+    } else if (this._termination) {
+      test.result = TestResult.Terminated;
+    } else {
+      // Otherwise, run the test itself if there is no scheduled termination.
       this._runningUserCallbacks.set(workerId, test._userCallback);
-    const error = await test._userCallback.run(state, test);
+      test.error = await test._userCallback.run(state, test);
       this._runningUserCallbacks.delete(workerId, test._userCallback);
-    if (this._termination)
+      if (!test.error)
-      return;
-    test.error = error;
-    if (!error)
         test.result = TestResult.Ok;
       else if (test.error === TimeoutError)
         test.result = TestResult.TimedOut;
+      else if (test.error === TerminatedError)
+        test.result = TestResult.Terminated;
       else
         test.result = TestResult.Failed;
+    }
+    for (let i = suitesStack.length - 1; i >= 0; i--)
+      crashed = (await this._runHook(workerId, suitesStack[i], 'afterEach', state, test)) || crashed;
+    // If some of the afterEach hooks error'ed - then this test is considered to be crashed as well.
+    if (crashed)
+      test.result = TestResult.Crashed;
     this._runner._didFinishTest(test, workerId);
     if (this._breakOnFailure && test.result !== TestResult.Ok)
-      this._terminate(`Terminating because a test has failed and |testRunner.breakOnFailure| is enabled`, null);
+      this._terminate(TestResult.Terminated, `Terminating because a test has failed and |testRunner.breakOnFailure| is enabled`, null);
   }
 
   async _runHook(workerId, suite, hookName, ...args) {
     const hook = suite[hookName];
     if (!hook)
-      return;
+      return false;
     this._runningUserCallbacks.set(workerId, hook);
     const error = await hook.run(...args);
     this._runningUserCallbacks.delete(workerId, hook);
     if (error === TimeoutError) {
       const location = `${hook.location.fileName}:${hook.location.lineNumber}:${hook.location.columnNumber}`;
       const message = `${location} - Timeout Exceeded ${hook.timeout}ms while running "${hookName}" in suite "${suite.fullName}"`;
-      this._terminate(message, null);
+      return this._terminate(TestResult.Crashed, message, null);
-    } else if (error) {
+    }
+    if (error) {
       const location = `${hook.location.fileName}:${hook.location.lineNumber}:${hook.location.columnNumber}`;
       const message = `${location} - FAILED while running "${hookName}" in suite "${suite.fullName}"`;
-      this._terminate(message, error);
+      return this._terminate(TestResult.Crashed, message, error);
     }
+    return false;
   }
 
-  _terminate(message, error) {
+  _terminate(result, message, error) {
     if (this._termination)
-      return;
+      return false;
-    this._termination = {message, error};
+    this._termination = {result, message, error};
     for (const userCallback of this._runningUserCallbacks.valuesArray())
       userCallback.terminate();
+    return true;
   }
 }
 
@@ -351,16 +367,22 @@ class TestRunner extends EventEmitter {
     this._runningPass = new TestPass(this, this._rootSuite, runnableTests, this._parallel, this._breakOnFailure);
     const termination = await this._runningPass.run();
     this._runningPass = null;
-    if (termination)
+    const result = {};
-      this.emit(TestRunner.Events.Terminated, termination.message, termination.error);
+    if (termination) {
-    else
+      result.result = termination.result;
-      this.emit(TestRunner.Events.Finished);
+      result.terminationMessage = termination.message;
+      result.terminationError = termination.error;
+    } else {
+      result.result = this.failedTests().length ? TestResult.Failed : TestResult.Ok;
+    }
+    this.emit(TestRunner.Events.Finished, result);
+    return result;
   }
 
   terminate() {
     if (!this._runningPass)
       return;
-    this._runningPass._terminate('Terminated with |TestRunner.terminate()| call', null);
+    this._runningPass._terminate(TestResult.Terminated, 'Terminated with |TestRunner.terminate()| call', null);
   }
 
   timeout() {
@@ -405,7 +427,7 @@ class TestRunner extends EventEmitter {
   }
 
   failedTests() {
-    return this._tests.filter(test => test.result === 'failed' || test.result === 'timedout');
+    return this._tests.filter(test => test.result === 'failed' || test.result === 'timedout' || test.result === 'crashed');
   }
 
   passedTests() {
@@ -442,10 +464,9 @@ function assert(value, message) {
 
 TestRunner.Events = {
   Started: 'started',
+  Finished: 'finished',
   TestStarted: 'teststarted',
   TestFinished: 'testfinished',
-  Terminated: 'terminated',
-  Finished: 'finished',
 };
 
 module.exports = TestRunner;

utils/testrunner/test/testrunner.spec.js

@@ -204,6 +204,58 @@ module.exports.addTests = function({testRunner, expect}) {
       for (let i = 1; i < states.length; ++i)
         expect(states[i]).toBe(states[0]);
     });
+    it('should unwind hooks properly when terminated', async() => {
+      const log = [];
+      const t = new TestRunner({timeout: 10000});
+      t.beforeAll(() => log.push('beforeAll'));
+      t.beforeEach(() => log.push('beforeEach'));
+      t.afterEach(() => log.push('afterEach'));
+      t.afterAll(() => log.push('afterAll'));
+      t.it('uno', () => {
+        log.push('terminating...');
+        t.terminate();
+      });
+      await t.run();
+
+      expect(log).toEqual([
+        'beforeAll',
+        'beforeEach',
+        'terminating...',
+        'afterEach',
+        'afterAll',
+      ]);
+    });
+    it('should unwind hooks properly when crashed', async() => {
+      const log = [];
+      const t = new TestRunner({timeout: 10000});
+      t.beforeAll(() => log.push('root beforeAll'));
+      t.beforeEach(() => log.push('root beforeEach'));
+      t.describe('suite', () => {
+        t.beforeAll(() => log.push('suite beforeAll'));
+        t.beforeEach(() => log.push('suite beforeEach'));
+        t.it('uno', () => log.push('uno'));
+        t.afterEach(() => {
+          log.push('CRASH >> suite afterEach');
+          throw new Error('crash!');
+        });
+        t.afterAll(() => log.push('suite afterAll'));
+      });
+      t.afterEach(() => log.push('root afterEach'));
+      t.afterAll(() => log.push('root afterAll'));
+      await t.run();
+
+      expect(log).toEqual([
+        'root beforeAll',
+        'suite beforeAll',
+        'root beforeEach',
+        'suite beforeEach',
+        'uno',
+        'CRASH >> suite afterEach',
+        'root afterEach',
+        'suite afterAll',
+        'root afterAll'
+      ]);
+    });
   });
 
   describe('TestRunner.run', () => {
@@ -345,6 +397,43 @@ module.exports.addTests = function({testRunner, expect}) {
     });
   });
 
+  describe('TestRunner.run result', () => {
+    it('should return OK if all tests pass', async() => {
+      const t = new TestRunner();
+      t.it('uno', () => {});
+      const result = await t.run();
+      expect(result.result).toBe('ok');
+    });
+    it('should return FAIL if at least one test fails', async() => {
+      const t = new TestRunner();
+      t.it('uno', () => { throw new Error('woof'); });
+      const result = await t.run();
+      expect(result.result).toBe('failed');
+    });
+    it('should return FAIL if at least one test times out', async() => {
+      const t = new TestRunner({timeout: 1});
+      t.it('uno', async() => new Promise(() => {}));
+      const result = await t.run();
+      expect(result.result).toBe('failed');
+    });
+    it('should return TERMINATED if it was terminated', async() => {
+      const t = new TestRunner({timeout: 1});
+      t.it('uno', async() => new Promise(() => {}));
+      const [result] = await Promise.all([
+        t.run(),
+        t.terminate(),
+      ]);
+      expect(result.result).toBe('terminated');
+    });
+    it('should return CRASHED if it crashed', async() => {
+      const t = new TestRunner({timeout: 1});
+      t.it('uno', async() => new Promise(() => {}));
+      t.afterAll(() => { throw new Error('woof');});
+      const result = await t.run();
+      expect(result.result).toBe('crashed');
+    });
+  });
+
   describe('TestRunner parallel', () => {
     it('should run tests in parallel', async() => {
       const log = [];
@@ -419,6 +508,14 @@ module.exports.addTests = function({testRunner, expect}) {
       expect(test1.result).toBe('failed');
       expect(test2.result).toBe('timedout');
     });
+    it('should report crashed tests', async() => {
+      const t = new TestRunner();
+      t.beforeEach(() => { throw new Error('woof');});
+      t.it('uno', () => {});
+      await t.run();
+      expect(t.failedTests().length).toBe(1);
+      expect(t.failedTests()[0].result).toBe('crashed');
+    });
   });
 
   describe('TestRunner.skippedTests', () => {
@@ -434,88 +531,79 @@ module.exports.addTests = function({testRunner, expect}) {
     });
   });
 
-  describe('TestRunner.on("terminated")', () => {
+  describe('Test.result', () => {
-    it('should terminate when hook crashes', async() => {
+    it('should return OK', async() => {
-      const log = [];
+      const t = new TestRunner();
-      const t = new TestRunner({timeout: 1});
+      t.it('uno', () => {});
-      t.beforeEach(() => log.push('beforeEach'));
+      await t.run();
-      t.it('test#1', () => log.push('test#1'));
+      expect(t.tests()[0].result).toBe('ok');
-      t.it('test#2', () => log.push('test#2'));
-      t.afterEach(() => { throw new Error('crash'); });
-      await Promise.all([
-        new Promise(x => t.once('terminated', x)),
-        t.run(),
-      ]);
-      expect(t.failedTests().length).toBe(0);
-      expect(log).toEqual([
-        'beforeEach',
-        'test#1'
-      ]);
     });
-    it('should terminate when hook times out', async() => {
+    it('should return TIMEDOUT', async() => {
-      const log = [];
       const t = new TestRunner({timeout: 1});
-      t.beforeEach(() => log.push('beforeEach'));
+      t.it('uno', async() => new Promise(() => {}));
-      t.it('test#1', () => log.push('test#1'));
+      await t.run();
-      t.it('test#2', () => log.push('test#2'));
+      expect(t.tests()[0].result).toBe('timedout');
-      t.afterEach(() => new Promise(() => {}));
+    });
-      await Promise.all([
+    it('should return SKIPPED', async() => {
-        new Promise(x => t.once('terminated', x)),
+      const t = new TestRunner();
-        t.run(),
+      t.xit('uno', () => {});
-      ]);
+      await t.run();
-      expect(t.failedTests().length).toBe(0);
+      expect(t.tests()[0].result).toBe('skipped');
-      expect(log).toEqual([
+    });
-        'beforeEach',
+    it('should return FAILED', async() => {
-        'test#1'
+      const t = new TestRunner();
-      ]);
+      t.it('uno', async() => Promise.reject('woof'));
+      await t.run();
+      expect(t.tests()[0].result).toBe('failed');
+    });
+    it('should return TERMINATED', async() => {
+      const t = new TestRunner();
+      t.it('uno', async() => t.terminate());
+      await t.run();
+      expect(t.tests()[0].result).toBe('terminated');
+    });
+    it('should return CRASHED', async() => {
+      const t = new TestRunner();
+      t.it('uno', () => {});
+      t.afterEach(() => {throw new Error('foo');});
+      await t.run();
+      expect(t.tests()[0].result).toBe('crashed');
     });
   });
 
-  describe('TestRunner.terminate', () => {
+  describe('TestRunner Events', () => {
-    it('should unwind hooks properly', async() => {
+    it('should emit events in proper order', async() => {
       const log = [];
-      const t = new TestRunner({timeout: 10000});
+      const t = new TestRunner();
       t.beforeAll(() => log.push('beforeAll'));
       t.beforeEach(() => log.push('beforeEach'));
+      t.it('test#1', () => log.push('test#1'));
       t.afterEach(() => log.push('afterEach'));
       t.afterAll(() => log.push('afterAll'));
-      t.it('uno', () => new Promise(() => {}));
+      t.on('started', () => log.push('E:started'));
-
+      t.on('teststarted', () => log.push('E:teststarted'));
-      await Promise.all([
+      t.on('testfinished', () => log.push('E:testfinished'));
-        t.run(),
+      t.on('finished', () => log.push('E:finished'));
-        new Promise(x => t.once('teststarted', x)).then(() => {
+      await t.run();
-          log.push('terminating...');
-          t.terminate();
-        }),
-      ]);
-
       expect(log).toEqual([
+        'E:started',
         'beforeAll',
+        'E:teststarted',
         'beforeEach',
-        'terminating...',
+        'test#1',
         'afterEach',
+        'E:testfinished',
         'afterAll',
+        'E:finished',
       ]);
     });
-    it('should unwind hooks even when they crash themselves', async() => {
+    it('should emit finish event with result', async() => {
-      const log = [];
+      const t = new TestRunner();
-      const t = new TestRunner({timeout: 10000});
+      const [result] = await Promise.all([
-      t.afterEach(() => { throw new Error('crash!'); });
+        new Promise(x => t.once('finished', x)),
-      t.afterAll(() => log.push('afterAll'));
-      t.it('uno', () => new Promise(() => {}));
-
-      await Promise.all([
         t.run(),
-        new Promise(x => t.once('teststarted', x)).then(() => {
-          log.push('terminating...');
-          t.terminate();
-        }),
-      ]);
-
-      expect(log).toEqual([
-        'terminating...',
-        'afterAll',
       ]);
+      expect(result.result).toBe('ok');
     });
   });
 };