feat(testrunner): catch delegate errors (#1704)

This ensures we get a proper error when something goes wrong. Should
also help with producing the right error code in the case of internal error.

Drive-by: fix location issue which manifests on the bots.
Drive-by: remove the use of Array.prototype.flat to make it work on bots.

utils/testrunner/Location.js

@@ -15,7 +15,10 @@
  * limitations under the License.
  */
 
- const path = require('path');
+const path = require('path');
+
+// Hack for our own tests.
+const testRunnerTestFile = path.join(__dirname, 'test', 'testrunner.spec.js');
 
 class Location {
   constructor() {
@@ -69,7 +72,7 @@ class Location {
       if (!match)
         return null;
       const filePath = match[1];
-      if (filePath === __filename || filePath.startsWith(ignorePrefix))
+      if (filePath === __filename || (filePath.startsWith(ignorePrefix) && filePath !== testRunnerTestFile))
         continue;
 
       location._filePath = filePath;

utils/testrunner/Matchers.js

@@ -102,8 +102,6 @@ function stringFormatter(received, expected) {
 }
 
 function objectFormatter(received, expected) {
-  const receivedLines = received.split('\n');
-  const expectedLines = expected.split('\n');
   const encodingMap = new Map();
   const decodingMap = new Map();
 
@@ -142,8 +140,12 @@ function objectFormatter(received, expected) {
     if (type === 1)
       return lines.map(line => '+   ' + colors.bgGreen.black(line));
     return lines.map(line => '    ' + line);
-  }).flat().join('\n');
+  });
-  return `Received:\n${highlighted}`;
+
+  const flattened = [];
+  for (const list of highlighted)
+    flattened.push(...list);
+  return `Received:\n${flattened.join('\n')}`;
 }
 
 function toBeFormatter(received, expected) {

utils/testrunner/TestRunner.js

@@ -302,13 +302,13 @@ class TestWorker {
   async _willStartTestRun(testRun) {
     testRun._startTimestamp = Date.now();
     testRun._workerId = this._workerId;
-    await this._testRunner._delegate.onTestRunStarted(testRun);
+    await this._testRunner._runDelegateCallback(this._testRunner._delegate.onTestRunStarted, [testRun]);
   }
 
   async _didFinishTestRun(testRun) {
     testRun._endTimestamp = Date.now();
     testRun._workerId = this._workerId;
-    await this._testRunner._delegate.onTestRunFinished(testRun);
+    await this._testRunner._runDelegateCallback(this._testRunner._delegate.onTestRunFinished, [testRun]);
   }
 
   async _willStartTestBody(testRun) {
@@ -352,6 +352,26 @@ class TestRunner {
     this._result = null;
   }
 
+  async _runDelegateCallback(callback, args) {
+    let { promise, terminate } = runUserCallback(callback, this._hookTimeout, args);
+    // Note: we do not terminate the delegate to keep reporting even when terminating.
+    const e = await promise;
+    if (e) {
+      debug('testrunner')(`Error while running delegate method: ${e}`);
+      const { message, error } = this._toError('INTERNAL ERROR', e);
+      this._terminate(TestResult.Crashed, message, false, error);
+    }
+  }
+
+  _toError(message, error) {
+    if (!(error instanceof Error)) {
+      message += ': ' + error;
+      error = new Error();
+      error.stack = '';
+    }
+    return { message, error };
+  }
+
   async run(testRuns, options = {}) {
     const {
       parallel = 1,
@@ -360,7 +380,7 @@ class TestRunner {
       totalTimeout = 0,
       onStarted = async (testRuns) => {},
       onFinished = async (result) => {},
-      onTestRunStarted = async(testRun) => {},
+      onTestRunStarted = async (testRun) => {},
       onTestRunFinished = async (testRun) => {},
     } = options;
     this._breakOnFailure = breakOnFailure;
@@ -374,34 +394,16 @@ class TestRunner {
 
     this._result = new Result();
     this._result.runs = testRuns;
-    await this._delegate.onStarted(testRuns);
-
-    let timeoutId;
-    if (totalTimeout) {
-      timeoutId = setTimeout(() => {
-        this._terminate(TestResult.Terminated, `Total timeout of ${totalTimeout}ms reached.`, true /* force */, null /* error */);
-      }, totalTimeout);
-    }
 
     const handleSIGINT = () => this._terminate(TestResult.Terminated, 'SIGINT received', false, null);
     const handleSIGHUP = () => this._terminate(TestResult.Terminated, 'SIGHUP received', false, null);
     const handleSIGTERM = () => this._terminate(TestResult.Terminated, 'SIGTERM received', true, null);
-    const handleRejection = error => {
+    const handleRejection = e => {
-      let message = 'UNHANDLED PROMISE REJECTION';
+      const { message, error } = this._toError('UNHANDLED PROMISE REJECTION', e);
-      if (!(error instanceof Error)) {
-        message += ': ' + error;
-        error = new Error();
-        error.stack = '';
-      }
       this._terminate(TestResult.Crashed, message, false, error);
     };
-    const handleException = error => {
+    const handleException = e => {
-      let message = 'UNHANDLED ERROR';
+      const { message, error } = this._toError('UNHANDLED ERROR', e);
-      if (!(error instanceof Error)) {
-        message += ': ' + error;
-        error = new Error();
-        error.stack = '';
-      }
       this._terminate(TestResult.Crashed, message, false, error);
     };
     process.on('SIGINT', handleSIGINT);
@@ -410,6 +412,14 @@ class TestRunner {
     process.on('unhandledRejection', handleRejection);
     process.on('uncaughtException', handleException);
 
+    let timeoutId;
+    if (totalTimeout) {
+      timeoutId = setTimeout(() => {
+        this._terminate(TestResult.Terminated, `Total timeout of ${totalTimeout}ms reached.`, true /* force */, null /* error */);
+      }, totalTimeout);
+    }
+    await this._runDelegateCallback(this._delegate.onStarted, [testRuns]);
+
     const workerCount = Math.min(parallel, testRuns.length);
     const workerPromises = [];
     for (let i = 0; i < workerCount; ++i) {
@@ -418,23 +428,18 @@ class TestRunner {
     }
     await Promise.all(workerPromises);
 
+    if (testRuns.some(run => run.isFailure()))
+      this._result.setResult(TestResult.Failed, '');
+
+    await this._runDelegateCallback(this._delegate.onFinished, [this._result]);
+    clearTimeout(timeoutId);
+
     process.removeListener('SIGINT', handleSIGINT);
     process.removeListener('SIGHUP', handleSIGHUP);
     process.removeListener('SIGTERM', handleSIGTERM);
     process.removeListener('unhandledRejection', handleRejection);
     process.removeListener('uncaughtException', handleException);
-
+    return this._result;
-    if (testRuns.some(run => run.isFailure()))
-      this._result.setResult(TestResult.Failed, '');
-
-    clearTimeout(timeoutId);
-    await this._delegate.onFinished(this._result);
-
-    const result = this._result;
-    this._result = null;
-    this._workers = [];
-    this._terminating = false;
-    return result;
   }
 
   async _runWorker(testRunIndex, testRuns, parallelIndex) {

utils/testrunner/test/testrunner.spec.js

@@ -822,6 +822,23 @@ module.exports.addTests = function({describe, fdescribe, xdescribe, it, xit, fit
       ]);
       expect(result.result).toBe('ok');
     });
+    it('should crash when onStarted throws', async() => {
+      const t = new Runner({
+        onStarted: () => { throw 42; },
+      });
+      const result = await t.run();
+      expect(result.ok()).toBe(false);
+      expect(result.message).toBe('INTERNAL ERROR: 42');
+    });
+    it('should crash when onFinished throws', async() => {
+      const t = new Runner({
+        onFinished: () => { throw new Error('42'); },
+      });
+      const result = await t.run();
+      expect(result.ok()).toBe(false);
+      expect(result.message).toBe('INTERNAL ERROR');
+      expect(result.result).toBe('crashed');
+    });
   });
 };