fix: enhance debugging experience of unhandled rejections

.eslintignore

@@ -4,3 +4,6 @@ examples
 src/browser/client-scripts/rrweb-record.min.js
 bundle.compat.js
 bundle.native.js
+wt
+test/e2e/report
+tmp

.gitignore

@@ -18,3 +18,5 @@ npm-debug.log
 hermione-report
 bundle.compat.js
 bundle.native.js
+wt/**
+tmp/**

.prettierignore

@@ -8,3 +8,6 @@ examples
 src/browser/client-scripts/rrweb-record.min.js
 bundle.compat.js
 bundle.native.js
+wt/**
+test/e2e/report
+tmp/**

src/browser-pool/cancelled-error.ts

@@ -3,7 +3,13 @@
  */
 export class CancelledError extends Error {
     name = "CancelledError";
-    message = "Browser request was cancelled";
+    message = `Browser request was cancelled
+
+What happened:
+- This test tried to run in a browser that was already stopped
+- This likely happened due to a critical error, like an unhandled promise rejection
+What you can do:
+- Check other failed tests or execution logs for more details, usually you can find the root cause there`;
 
     constructor() {
         super();

src/browser-pool/limited-pool.ts

@@ -79,17 +79,17 @@ export class LimitedPool implements Pool {
         return this.underlyingPool.freeBrowser(browser, optsForFree).finally(() => this._launchNextBrowser());
     }
 
-    cancel(): void {
+    cancel(error: Error = new CancelledError()): void {
         this.log("cancel");
 
-        const reject_ = (entry: QueueItem): void => entry.reject(new CancelledError());
+        const reject_ = (entry: QueueItem): void => entry.reject(error);
         this._highPriorityRequestQueue.forEach(reject_);
         this._requestQueue.forEach(reject_);
 
         this._highPriorityRequestQueue = yallist.create();
         this._requestQueue = yallist.create();
 
-        this.underlyingPool.cancel();
+        this.underlyingPool.cancel(error);
     }
 
     private async _getBrowser(id: string, opts: BrowserOpts = {}): Promise<Browser> {

src/browser-pool/per-browser-limited-pool.ts

@@ -5,6 +5,7 @@ import { Pool } from "./types";
 import { Config } from "../config";
 import { Browser } from "../browser/browser";
 import { LimitedPool } from "./limited-pool";
+import { CancelledError } from "./cancelled-error";
 
 export class PerBrowserLimitedPool implements Pool {
     log: debug.Debugger;
@@ -36,8 +37,8 @@ export class PerBrowserLimitedPool implements Pool {
         return this._browserPools[browser.id].freeBrowser(browser, opts);
     }
 
-    cancel(): void {
+    cancel(error: Error = new CancelledError()): void {
         this.log("cancel");
-        forEach(this._browserPools, pool => pool.cancel());
+        forEach(this._browserPools, pool => pool.cancel(error));
     }
 }

src/browser-pool/types.ts

@@ -3,7 +3,7 @@ import { Browser } from "../browser/browser";
 export interface Pool<T extends Browser = Browser> {
     getBrowser(id: string, opts?: object): Promise<T>;
     freeBrowser(browser: T, opts?: object): Promise<void>;
-    cancel(): void;
+    cancel(error?: Error): void;
 }
 
 export interface BrowserOpts {

src/cli/index.ts

@@ -21,15 +21,17 @@ process.on("uncaughtException", err => {
     process.exit(1);
 });
 
-process.on("unhandledRejection", (reason, p) => {
+process.on("unhandledRejection", reason => {
+    // This flag lets other unhandledRejection handlers know that we already processed it on Testplane side.
+    // Currently we use this to avoid duplicate error logging and force shutdown in HTML Reporter.
+    (global as Record<string, unknown>)["__TESTPLANE_INTERNAL_UNHANDLED_REJECTION_PROCESSED"] = true;
     if (shouldIgnoreUnhandledRejection(reason as Error)) {
         logger.warn(`Unhandled Rejection "${reason}" in testplane:master:${process.pid} was ignored`);
         return;
     }
 
     const error = [
         `Unhandled Rejection in testplane:master:${process.pid}:`,
-        `Promise: ${utilInspectSafe(p)}`,
         `Reason: ${utilInspectSafe(reason)}`,
     ].join("\n");
 

src/constants/process-messages.ts

@@ -4,3 +4,4 @@ export const MASTER_SYNC_CONFIG = "master.syncConfig";
 export const WORKER_INIT = "worker.init";
 export const WORKER_SYNC_CONFIG = "worker.syncConfig";
 export const WORKER_UNHANDLED_REJECTION = "worker.unhandledRejection";
+export const TEST_ASSIGNED_TO_WORKER = "worker.testAssignedToWorker";

src/errors/unhandled-rejection-error.ts

@@ -0,0 +1,32 @@
+interface UnhandledRejectionErrorDetails {
+    testsHint: string;
+    workerPid?: number;
+    error: Error;
+}
+
+export class UnhandledRejectionError extends Error {
+    constructor(details: UnhandledRejectionErrorDetails) {
+        const lines: Array<string> = [];
+        lines.push("This run has been terminated due to an unhandled promise rejection.\n");
+
+        lines.push("What happened:");
+        lines.push("- A promise rejected without being handled");
+
+        lines.push("What you can do:");
+        lines.push('- Analyze error below and check your tests for missing "await" statements');
+        lines.push(
+            "- Turn on the @typescript-eslint/no-floating-promises rule to catch\n" +
+                '  missing "await" statements automatically (works even for js files!)',
+        );
+
+        if (details.testsHint) {
+            lines.push(`\nThe error most likely originated from one of the tests below.\n${details.testsHint}`);
+        }
+
+        lines.push(`\nError details: ${details.error.message}\n${details.error.stack}`);
+
+        super(lines[0]);
+        this.stack = lines.join("\n");
+        this.name = "UnhandledRejectionTerminatedError";
+    }
+}

src/events/index.ts

@@ -34,6 +34,7 @@ export const RunnerSyncEvents = {
     SUITE_END: "endSuite",
 
     TEST_BEGIN: "beginTest",
+    TEST_ASSIGNED_TO_WORKER: "testAssignedToWorker",
     TEST_END: "endTest",
 
     TEST_PASS: "passTest",

src/reporters/flat.js

@@ -4,6 +4,7 @@ const _ = require("lodash");
 const BaseReporter = require("./base");
 const helpers = require("./utils/helpers");
 const icons = require("./utils/icons");
+const { withLogOptions } = require("../utils/logger");
 
 module.exports = class FlatReporter extends BaseReporter {
     constructor(...args) {
@@ -29,18 +30,23 @@ module.exports = class FlatReporter extends BaseReporter {
 
         const failedTests = helpers.formatFailedTests(this._tests);
 
+        const noTimestamp = withLogOptions({ timestamp: false });
+
         failedTests.forEach((test, index) => {
-            this.informer.log(`\n${index + 1}) ${test.fullTitle}`);
-            this.informer.log(`   in file ${test.file}\n`);
+            this.informer.log(`\n${index + 1}) ${test.fullTitle}`, noTimestamp);
+            this.informer.log(`   in file ${test.file}\n`, noTimestamp);
 
             _.forEach(test.browsers, testCase => {
                 const icon = testCase.isFailed ? icons.FAIL : icons.RETRY;
 
-                this.informer.log(`   ${testCase.browserId}`);
+                this.informer.log(`   ${testCase.browserId}`, noTimestamp);
                 if (testCase.errorSnippet) {
-                    testCase.errorSnippet.split("\n").forEach(line => this.informer.log(line));
+                    testCase.errorSnippet.split("\n").forEach(line => this.informer.log(line, noTimestamp));
                 }
-                this.informer.log(`     ${icon} ${testCase.error}`);
+                this.informer.log(
+                    `${icon} ${testCase.error}`,
+                    withLogOptions({ timestamp: false, prefixEachLine: " ".repeat(4) }),
+                );
             });
         });
     }

src/reporters/informers/console.js

@@ -2,16 +2,16 @@ const BaseInformer = require("./base");
 const logger = require("../../utils/logger");
 
 module.exports = class ConsoleInformer extends BaseInformer {
-    log(message) {
-        logger.log(message);
+    log(...args) {
+        logger.log(...args);
     }
 
-    warn(message) {
-        logger.warn(message);
+    warn(...args) {
+        logger.warn(...args);
     }
 
-    error(message) {
-        logger.error(message);
+    error(...args) {
+        logger.error(...args);
     }
 
     end(message) {

src/reporters/informers/file.js

@@ -14,16 +14,25 @@ module.exports = class FileInformer extends BaseInformer {
         logger.log(`Information with test results for report: "${opts.type}" will be saved to a file: "${opts.path}"`);
     }
 
-    log(message) {
-        this._fileStream.write(`${this._prepareMsg(message)}\n`);
+    log(...args) {
+        const lastArg = args[args.length - 1];
+        const isLogOptions = lastArg && typeof lastArg === "object" && Symbol.for("logOptions") in lastArg;
+
+        if (isLogOptions) {
+            args.pop();
+        }
+
+        args.forEach(message => {
+            this._fileStream.write(`${this._prepareMsg(message)}\n`);
+        });
     }
 
-    warn(message) {
-        this.log(message);
+    warn(...args) {
+        this.log(...args);
     }
 
-    error(message) {
-        this.log(message);
+    error(...args) {
+        this.log(...args);
     }
 
     end(message) {

src/reporters/plain.js

@@ -5,6 +5,7 @@ const chalk = require("chalk");
 const BaseReporter = require("./base");
 const icons = require("./utils/icons");
 const helpers = require("./utils/helpers");
+const { withLogOptions } = require("../utils/logger");
 
 module.exports = class PlainReporter extends BaseReporter {
     _logTestInfo(test, icon) {
@@ -13,8 +14,10 @@ module.exports = class PlainReporter extends BaseReporter {
         if (icon === icons.RETRY || icon === icons.FAIL) {
             const testInfo = helpers.getTestInfo(test);
 
-            this.informer.log(`   in file ${testInfo.file}`);
-            this.informer.log(`   ${chalk.red(testInfo.error)}`);
+            const noTimestampAndPrefix = withLogOptions({ timestamp: false, prefixEachLine: " ".repeat(4) });
+
+            this.informer.log(`in file ${testInfo.file}`, noTimestampAndPrefix);
+            this.informer.log(`${chalk.red(testInfo.error)}`, noTimestampAndPrefix);
         }
     }
 };

src/runner/browser-runner.ts

@@ -85,8 +85,8 @@ export class BrowserRunner extends CancelableEmitter {
         this.activeTestRunners.delete(runner);
     }
 
-    cancel(): void {
-        this.activeTestRunners.forEach(runner => runner.cancel());
+    cancel(error: Error): void {
+        this.activeTestRunners.forEach(runner => runner.cancel(error));
     }
 
     private passthroughEvents(runner: EventEmitter, events: InterceptedEvent[]): void {

src/runner/index.ts

@@ -77,6 +77,7 @@ export class MainRunner extends RunnableEmitter {
             MasterEvents.DOM_SNAPSHOTS,
             MasterEvents.ADD_FILE_TO_REMOVE,
             MasterEvents.TEST_DEPENDENCIES,
+            MasterEvents.TEST_ASSIGNED_TO_WORKER,
         ]);
 
         temp.init(this.config.system.tempDir);
@@ -201,13 +202,15 @@ export class MainRunner extends RunnableEmitter {
         );
     }
 
-    cancel(): void {
+    cancel(error: Error): void {
         this.cancelled = true;
-        this.browserPool?.cancel();
+        this.browserPool?.cancel(error);
 
-        this.activeBrowserRunners.forEach(runner => runner.cancel());
+        this.activeBrowserRunners.forEach(runner => runner.cancel(error));
 
-        this.workers?.cancel();
+        this.workers?.cancel().catch(() => {
+            /* we can just ignore the error thrown, because we don't care about cleanup at this point */
+        });
     }
 
     registerWorkers<T extends ReadonlyArray<string>>(workerFilepath: string, exportedMethods: T): RegisterWorkers<T> {