refactor: automatically aborb browser error after abort signal

Author: Krinkle

API.md

@@ -26,32 +26,24 @@ module.exports = {
 
 ## QTap browser interface
 
-Browsers are defined by implementing a launcher function with the following signature. Launchers are either an async function, or a function that returns a Promise.
+You can define a browser launcher by implementing a function with the following signature. These launchers should either be async functions, or functions that return a Promise.
 
 ```js
 /**
- * A browser launcher is responsible for knowing whether the process failed to
- * launch or spawn, and whether it exited unexpectedly.
+ * A browser launcher is responsible for opening a URL in the browser.
  *
- * A launcher is not responsible for knowing whether it succeeded in
- * opening or navigating to the given URL.
+ * A launcher is not responsible for knowing whether the browser succeeded in
+ * opening or navigating to this URL.
  *
- * It is the responsiblity of ControlServer to send the "abort" event
- * to AbortSignal if it believes the browser has failed to load the
- * URL within a reasonable timeout, or if the browser has not sent
- * any message for a while.
- *
- * If a browser exits on its own (i.e. ControlServer did not call send
- * an abort signal), then launch() should throw an Error or reject its
- * returned Promise.
+ * If a browser crashes or otherwise exits unexpectedly,
+ * you should throw an Error or reject your returned Promise.
  *
  * @param {string} url
  *  URL that the browser should navigate to, HTTP or HTTPS.
  * @param {AbortSignal} signal
- *  The launched browser process must be terminated when this signal
- *  receives an "abort" event. QTap sends the abort event when it finds that
- *  a test has finished, or if it needs to stop the browser for any other
- *  reason.
+ *  The browser process must be terminated when this signal receives an "abort" event.
+ *  QTap sends the "abort" event when it finds that a test run has finished, or if it
+ *  needs to stop the browser for any other reason.
  * @param {qtap-Logger} logger
  */
 async function myBrowserLauncher(url, signal, logger);

ARCHITECTURE.md

@@ -47,13 +47,13 @@ Examples:
 
 Performance is a first-class principle in QTap.
 
-The first priority (after the "Simple" and "Lean" values above) is time to first result. This means the CLI endpoint should as directly as possible launch browsers and start the ControlServer. Any computation, imports and other overhead is deferred when possible.
+The first priority (after the "Simple" and "Lean" values above) is time to first result. This means the CLI endpoint should as directly as possible start browsers and start the ControlServer. Any computation, imports and other overhead is deferred when possible.
 
 The second piority is time to last result (e.g. "Done!"), which is generally what a human in local development (especially in watch mode) will be waiting for. Note that this is separate from when the CLI process technically exits, which is less important to us. It is expected that the process will in practice exit immediately after the last result is printed, but when we have a choice, it is important to first get and communicate test results. In particular for watch mode, shutdown logic will not happen on re-runs and thus is avoided if we don't do it in the critical path toward obtaining test results.
 
 ## Debugging
 
-Set `QTAP_DEBUG=1` as environment variable, when calling the QTap CLI, to launch local browsers visibly instead of headless.
+Set `QTAP_DEBUG=1` as environment variable, when calling the QTap CLI, to start local browsers visibly instead of headless.
 
 Set `--verbose` in the QTap CLI to enable verbose debug logging.
 
@@ -122,11 +122,11 @@ Set `--verbose` in the QTap CLI to enable verbose debug logging.
 
 * **Page-side script injection**. The HTML file is modified to include an inline script that subscribes to `console.log` and other events, and beacons to our command-line process. More details at [QTap Internal: Client send](#qtap-internal-client-send).
 
-  This means browser can be launched by any means, pointed at a URL, and then forgotten about until we shut it down. It requires no control over the browser process. And the requirements for someone writing a browser launcher, is thus merely to open a single URL. More details at [QTap API: Browser launcher](#qtap-internal-client-send).
+  This means browser can be started by any means, pointed at a URL, and then forgotten about until we shut it down. It requires no control over the browser process. And the requirements for someone writing a browser launcher, is thus merely to open a single URL. More details at [QTap API: Browser launcher](#qtap-internal-client-send).
 
 ## QTap API: Browser launcher
 
-Each browser is implemented as a single async function that launches the browser. The function is called with all required information and services. The [injected](https://en.wikipedia.org/wiki/Dependency_injection) parameters include a URL, an abort signal, and a logger function.
+Each browser is implemented as a single async function that opens the browser. The function is called with all required information and services. The [injected](https://en.wikipedia.org/wiki/Dependency_injection) parameters include a URL, an abort signal, and a logger function.
 
 The function is expected to run as long as the browser is running, with the returned Promise representing the browser process. If the browser exits for any reason, you may run any cleanup and then return. If the browser fails or crashes for any reason, this can be conveyed by throwing an error (or rejecting a Promise) from your async function.
 
@@ -147,7 +147,7 @@ async function myBrowser (url, signal, logger) {
   const spawned = child_process.spawn('/bin/mybrowser', ['-headless', url], { signal });
   await new Promise((resolve, reject) => {
     spawned.on('error', (error) => reject(error));
-    spawned.on('exit', (code) => reject(new Error(`Process exited ${code}`)));
+    spawned.on('exit', () => reject(new Error('Process exited'));
   });
 }
 
@@ -240,12 +240,8 @@ async function myBrowser (url, signal, logger) {
   async function myBrowser (url, signal, logger) {
     const spawned = child_process.spawn('/bin/mybrowser', ['-headless', url], { signal });
     await new Promise((resolve, reject) => {
-      spawned.on('error', (error) => {
-        (signal.aborted ? resolve() : reject(error));
-      });
-      spawned.on('exit', () => {
-        (signal.aborted ? resolve(): reject(new Error('Process exited'));
-      });
+      spawned.on('error', (error) => reject(error));
+      spawned.on('exit', () => reject(new Error('Process exited'));
     });
   }
   ```

src/qtap.js

@@ -1,6 +1,7 @@
 'use strict';
 
 import util from 'node:util';
+import path from 'node:path';
 
 import kleur from 'kleur';
 import browsers from './browsers.js';
@@ -37,9 +38,11 @@ function makeLogger (defaultChannel, printDebug, verbose = false) {
         : function debug (messageCode, ...params) {
           printDebug(kleur.grey(`[${prefix}] ${kleur.bold(messageCode)} ${paramsFmt(params)}`));
         },
-      warning: function warning (messageCode, ...params) {
-        printDebug(kleur.yellow(`[${prefix}] WARNING ${kleur.bold(messageCode)}`) + ` ${paramsFmt(params)}`);
-      }
+      warning: !verbose
+        ? function () {}
+        : function warning (messageCode, ...params) {
+          printDebug(kleur.yellow(`[${prefix}] WARNING ${kleur.bold(messageCode)}`) + ` ${paramsFmt(params)}`);
+        }
     };
   }
 
@@ -74,8 +77,7 @@ function makeLogger (defaultChannel, printDebug, verbose = false) {
 
 /**
  * @param {string|string[]} browserNames One or more browser names, referring either
- *  to a built-in browser launcher from QTap, or to a key in the optional
- *  `config.browsers` object.
+ *  to a built-in browser from QTap, or to a key in the optional `config.browsers` object.
  * @param {string|string[]} files Files and/or URLs.
  * @param {qtap.RunOptions} [options]
  * @return {Promise<number>} Exit code. 0 is success, 1 is failed.
@@ -98,13 +100,18 @@ async function run (browserNames, files, options = {}) {
     }));
   }
 
-  // TODO: Add integration test for config file not found
-  // TODO: Add integration test for config file with runtime errors
-  const config = typeof options.config === 'string' ? await import(options.config) : options.config;
+  // TODO: Add test for config file not found
+  // TODO: Add test for config file with runtime errors
+  // TODO: Add test for relative config file without leading `./`, handled by process.resolve()
+  let config;
+  if (typeof options.config === 'string') {
+    logger.debug('load_config', options.config);
+    config = (await import(path.resolve(process.cwd(), options.config))).default;
+  }
   const globalController = new AbortController();
   const globalSignal = globalController.signal;
 
-  const browserLaunches = [];
+  const browerPromises = [];
   for (const browserName of browserNames) {
     logger.debug('get_browser', browserName);
     const browserFn = browsers[browserName] || config?.browsers?.[browserName];
@@ -114,18 +121,18 @@ async function run (browserNames, files, options = {}) {
     for (const server of servers) {
       // Each launchBrowser() returns a Promise that settles when the browser exits.
       // Launch concurrently, and await afterwards.
-      browserLaunches.push(server.launchBrowser(browserFn, browserName, globalSignal));
+      browerPromises.push(server.launchBrowser(browserFn, browserName, globalSignal));
     }
   }
 
   try {
     // Wait for all tests and browsers to finish/stop, regardless of errors thrown,
     // to avoid dangling browser processes.
-    await Promise.allSettled(browserLaunches);
+    await Promise.allSettled(browerPromises);
 
     // Re-wait, this time letting the first of any errors bubble up.
-    for (const launched of browserLaunches) {
-      await launched;
+    for (const browerPromise of browerPromises) {
+      await browerPromise;
     }
 
     logger.debug('shared_cleanup', 'Invoke global signal to clean up shared resources');
@@ -139,7 +146,7 @@ async function run (browserNames, files, options = {}) {
   }
 
   // TODO: Set exit status to 1 on failures, to ease programmatic use and testing.
-  // TODO: Return an event emitter for custom reportering via programmatic use.
+  // TODO: Return an event emitter for custom reporting via programmatic use.
   return 0;
 }
 

src/safari.js

@@ -80,19 +80,24 @@ async function safari (url, signals, logger) {
   }
 
   // Step 2: Create a session
+  // This re-tries indefinitely until safaridriver is ready, or until we get an abort signal.
   let session;
-  for (let i = 1; i <= 20; i++) {
+  for (let i = 1; true; i++) {
     try {
       session = await webdriverReq('POST', '/session/', { capabilities: { browserName: 'safari' } });
       // Connected!
       break;
     } catch (err) {
-      /** @type {any} - TypeScript can't set type without reassign, and @types/node lacks Error.code */
+      /** @type {any} - TypeScript @types/node lacks Error.code */
       const e = err;
       if (e.code === 'ECONNREFUSED' || (e.cause && e.cause.code === 'ECONNREFUSED')) {
-        // Wait for safaridriver to be ready, try again in another 10ms-200ms, upto ~2s in total.
-        logger.debug('safaridriver_waiting', `Attempt #${i}: ${e.code || e.cause.code}. Try again in ${i * 10}ms.`);
-        await new Promise(resolve => setTimeout(resolve, i * 10));
+        // Give up once QTap declared browser_connect_timeout
+        if (signals.browser.aborted) return;
+
+        // Back off from 50ms upto 1.0s each attempt
+        const wait = Math.min(i * 50, 1000);
+        logger.debug('safaridriver_waiting', `Attempt #${i}: ${e.code || e.cause.code}. Try again in ${wait}ms.`);
+        await new Promise(resolve => setTimeout(resolve, wait));
         continue;
       }
       logger.warning('safaridriver_session_error', e);
@@ -110,7 +115,7 @@ async function safari (url, signals, logger) {
 
   // Step 4: Close the tab once we receive an 'abort' signal.
   return await new Promise((resolve, reject) => {
-    signals.client.addEventListener('abort', async () => {
+    signals.browser.addEventListener('abort', async () => {
       try {
         await webdriverReq('DELETE', `/session/${session.sessionId}`);
         resolve();

src/server.js

@@ -43,8 +43,8 @@ class ControlServer {
     this.connectTimeout = options.connectTimeout || 60;
 
     this.browsers = new Map();
-    // Optimization: Prefetch test file in parallel with server starting and browser launching.
-    // Once browsers are launched and they make their first HTTP request,
+    // Optimization: Prefetch test file in parallel with server creation and browser launching.
+    // Once browsers are running and they make their first HTTP request,
     // we'll await this in handleRequest/getTestFile.
     this.testFilePromise = this.fetchTestFile(this.testFile);
 
@@ -111,55 +111,45 @@ class ControlServer {
 
     // TODO: Remove `summary` in favour of `eventbus`
     const summary = { ok: true };
+    let clientIdleTimer = null;
 
     const controller = new AbortController();
     let signal = controller.signal;
     if (QTAP_DEBUG) {
       // Replace with a dummy signal that we never invoke
       signal = (new AbortController()).signal;
       controller.signal.addEventListener('abort', () => {
-        logger.warning('browser_debugging_abort', 'Keeping browser open for debugging');
+        logger.warning('browser_signal_debugging', 'Keeping browser open for debugging');
       });
     }
 
-    // TODO: Write test for --connect-timeout by using a no-op browser.
-    const TIMEOUT_CONNECT = this.connectTimeout;
-    const TIMEOUT_IDLE = this.idleTimeout;
-    const TIMEOUT_CHECK_MS = 1000;
-    const launchStart = performance.now();
-    let clientIdleTimer = null;
-
     // Reasons to stop a browser, whichever comes first:
     // 1. tap-finished.
     // 2. tap-parser 'bailout' event (client knows it crashed).
     // 3. timeout (client didn't start, lost connection, or unknowingly crashed).
-    const stopBrowser = async (reason) => {
-      // NOTE: The below does not need to check browsers.get() before calling
-      // browsers.delete() or controller.abort(), because both of these are
-      // idempotent and safely ignore all but the first call.
-      // Hence we don't need to guard against race conditions where two reasons
-      // may both try to stop the same browser.
+    const stopBrowser = async (messageCode) => {
+      // Ignore any duplicate or late reasons to stop
+      if (!this.browsers.has(clientId)) return;
+
       clearTimeout(clientIdleTimer);
       this.browsers.delete(clientId);
-      controller.abort(reason);
+      controller.abort(`QTap: ${messageCode}`);
     };
 
     const tapParser = tapFinished({ wait: 0 }, () => {
-      logger.debug('browser_tap_finished', 'Test has finished, stopping browser');
-      stopBrowser('QTap: browser_tap_finished');
+      logger.debug('browser_tap_finished', 'Test run finished, stopping browser');
+      stopBrowser('browser_tap_finished');
     });
 
     tapParser.on('bailout', (reason) => {
-      logger.warning('browser_tap_bailout', `Test ended unexpectedly, stopping browser. Reason: ${reason}`);
-      summary.ok = false;
-      stopBrowser('QTap: browser_tap_bailout');
-    });
-    tapParser.once('fail', () => {
-      logger.debug('browser_tap_fail', 'Results indicate at least one test has failed assertions');
+      logger.warning('browser_tap_bailout', `Test run bailed, stopping browser. Reason: ${reason}`);
       summary.ok = false;
+      stopBrowser('browser_tap_bailout');
     });
     // Debugging
+    // tapParser.on('line', logger.debug.bind(logger, 'browser_tap_line'));
     // tapParser.on('assert', logger.debug.bind(logger, 'browser_tap_assert'));
+    // tapParser.once('fail', () => logger.debug('browser_tap_fail', 'Found one or more failing tests'));
     // tapParser.on('plan', logger.debug.bind(logger, 'browser_tap_plan'));
 
     const browser = {
@@ -176,37 +166,50 @@ class ControlServer {
     // in `handleTap()` or `tapParser.on('line')`. But that adds significant overhead from
     // Node.js/V8 natively allocating many timers when processing large batches of test results.
     // Instead, merely store performance.now() and check that periodically.
-    clientIdleTimer = setTimeout(function qtapCheckTimeout () {
-      // TODO: Report timeout failure to reporter/TAP/CLI.
+    // TODO: Write test for --connect-timeout by using a no-op browser.
+    const TIMEOUT_CHECK_MS = 1000;
+    const browserStart = performance.now();
+    const qtapCheckTimeout = () => {
       if (!browser.clientIdleActive) {
-        if ((performance.now() - launchStart) > (TIMEOUT_CONNECT * 1000)) {
-          logger.warning('browser_connect_timeout', `Browser did not start within ${TIMEOUT_CONNECT}s, stopping browser`);
+        if ((performance.now() - browserStart) > (this.connectTimeout * 1000)) {
+          logger.warning('browser_connect_timeout', `Browser did not start within ${this.connectTimeout}s, stopping browser`);
           summary.ok = false;
-          stopBrowser('QTap: browser_connect_timeout');
+          stopBrowser('browser_connect_timeout');
           return;
         }
       } else {
-        if ((performance.now() - browser.clientIdleActive) > (TIMEOUT_IDLE * 1000)) {
-          logger.warning('browser_idle_timeout', `Browser idle for ${TIMEOUT_IDLE}s, stopping browser`);
+        if ((performance.now() - browser.clientIdleActive) > (this.idleTimeout * 1000)) {
+          logger.warning('browser_idle_timeout', `Browser idle for ${this.idleTimeout}s, stopping browser`);
           summary.ok = false;
-          stopBrowser('QTap: browser_idle_timeout');
+          stopBrowser('browser_idle_timeout');
           return;
         }
       }
       clientIdleTimer = setTimeout(qtapCheckTimeout, TIMEOUT_CHECK_MS);
-    }, TIMEOUT_CHECK_MS);
+    };
+    clientIdleTimer = setTimeout(qtapCheckTimeout, TIMEOUT_CHECK_MS);
 
     const url = await this.getProxyBase() + '/?qtap_clientId=' + clientId;
-    const signals = { client: signal, global: globalSignal };
+    const signals = { browser: signal, global: globalSignal };
 
     try {
       logger.debug('browser_launch_call');
       await browserFn(url, signals, logger);
-      logger.debug('browser_launch_ended');
-    } finally {
+
+      // This stopBrowser() is most likely a no-op (e.g. if we received test results
+      // or some error, and we asked the browser to stop). Just in case the browser
+      // ended by itself, call it again here so that we can convey it as an error
+      // if it was still running from our POV.
+      logger.debug('browser_launch_exit');
+      stopBrowser('browser_launch_exit');
+    } catch (e) {
       // TODO: Report error to TAP. Eg. "No executable found"
       // TODO: logger.warning('browser_launch_exit', err); but catch in qtap.js?
-      stopBrowser('QTap: browser_launch_ended');
+      if (!signal.aborted) {
+        logger.warning('browser_launch_error', e);
+        stopBrowser('browser_launch_error');
+        throw e;
+      }
     }
   }