[WIP] bring back bailout, and cleanly separate launch from results

Starting the tapParser right away and inside the attempt, means when
we throw an exception for browser connect timeout, we have no way
to produce a finalResult / clientresult event. This is why bailout
was separate, but this is messy to deal with in reporters and also
makes partial results hard to transfer.

Instead, handle our bailout the same way as TAP bailout: As part
of the clientresult event, not as a separate event. Upstream tap-parser
emits finalResult#bailout, we can do the same in clientresult.

For this to work we need to make tap-finished trigger on bailout,
which it didn't until now.

The benefit of this is also that there is no longer any risk of
multiple browser attempts communicating over the same TAP stream
and producing duplicate or conflicting results because we do not
attach the TAP stream until after the browser has connected.

For additional disambiguation we also mint the clientId during the
attempt, instead of sharing it across retries.

Author: Krinkle

src/server.js

@@ -92,6 +92,7 @@ class ControlServer {
     this.connectTimeout = options.connectTimeout;
     this.debugMode = options.debugMode;
 
+    this.launchingBrowsers = new Set();
     this.browsers = new Map();
     // Optimization: Prefetch test file in parallel with server creation and browser launching.
     //
@@ -263,15 +264,9 @@ class ControlServer {
     const clientId = url.searchParams.get('qtap_clientId');
     if (clientId !== null) {
       // Serve the testfile from any URL path, as chosen by launchBrowser()
-      const browser = this.browsers.get(clientId);
-      if (browser) {
-        browser.logger.debug('browser_connected', `${browser.getDisplayName()} connected! Serving test file.`);
-        this.eventbus.emit('clientonline', {
-          clientId,
-          testFile: this.testFile + this.testFileQueryString,
-          browserName: browser.browserName,
-          displayName: browser.getDisplayName(),
-        });
+      if (this.launchingBrowsers.has(clientId)) {
+        this.launchingBrowsers.delete(clientId);
+        this.eventbus.emit('clientonline', { clientId });
       } else if (this.debugMode) {
         // Allow users to reload the page when in --debug mode.
         // Note that the results of this reload will not be reported, because
@@ -296,11 +291,6 @@ class ControlServer {
       resp.writeHead(200);
       resp.write(testFileResp.body);
       resp.end();
-
-      // Count proxying the test file toward connectTimeout, not idleTimeout.
-      if (browser) {
-        browser.clientIdleActive = performance.now();
-      }
       return;
     }
 
@@ -382,9 +372,95 @@ class ControlServer {
   }
 
   async launchBrowser (browserFn, browserName, globalSignal) {
-    const clientId = 'client_S' + this.serverId + '_C' + this.nextClientId++;
-    const logger = this.logger.channel(`qtap_browser_${clientId}_${browserName}`);
+    const maxTries = (browserFn.allowRetries === false || this.debugMode) ? 1 : 3;
+    let i = 1;
+    let browserPromise;
+    while (true) {
+      const clientId = 'client_S' + this.serverId + '_C' + this.nextClientId++;
+      const logger = this.logger.channel(`qtap_browser_${clientId}_${browserName}`);
+      const controller = new AbortController();
+      const signals = {
+        // NOTE: The browser signal tracks both "browser" and "global" controllers,
+        // so that if qtap.run() bails out (e.g. uncaught error from a reporter, or
+        // test server fails in fetchTestFile due to file not found), and if for
+        // some reason the natural shutdown fails (i.e. we don't call
+        // server.stopBrowsers or don't await browerPromise), then we have one
+        // last chance during shared_cleanup to stop dangling browser processes.
+        browser: AbortSignal.any([controller.signal, globalSignal]),
+        global: globalSignal
+      };
+      if (this.debugMode) {
+        // Replace with a dummy signal that we never invoke
+        //
+        // TODO: Refactor reporting and process mgmt so that results are reported
+        // on the CLI as normal. Right now, once the test finishes, the CLI doesn't
+        // report it because it waits to report until the browser exits. We need
+        // to create a way to keep report the results yet keep the process open.
+        signals.browser = (new AbortController()).signal;
+        signals.browser.addEventListener('abort', () => {
+          browser.logger.warning('browser_signal_debugging', 'Keeping browser open for debugging');
+        });
+      }
+
+      // TODO: rename browser=>client
+      const browser = {
+        clientId,
+        logger,
+        browserName,
+        getDisplayName () {
+          return browserFn.getDisplayName();
+        },
+        /**
+         * Reasons to stop a browser, whichever comes first:
+         * 1. tap-finished (client has sent us the test results).
+         * 2. tap-parser 'bailout' event (client knows it crashed).
+         * 3. connect timeout
+         * 4. idle timeout (client idle and presumed lost, or a silent crash).
+         *
+         * @param {any} reason
+         */
+        stop: async (reason) => {
+          if (!this.browsers.has(clientId)) {
+            // Ignore any duplicate or late reasons to stop
+            return;
+          }
+
+          this.browsers.delete(clientId);
+          controller.abort(reason);
+        }
+      };
+      try {
+        browserPromise = await this.launchBrowserAttempt(browserFn, browser, signals);
+        break;
+      } catch (e) {
+        // Do not retry uncaught errors from browserFn or client-side bailout,
+        // which are expected to be deterministic. Only retry BrowserConnectTimeout.
+        if (e instanceof util.BrowserConnectTimeout && i < maxTries) {
+          i++;
+          this.logger.debug('browser_connect_retry', `Retrying, attempt ${i} of ${maxTries}`);
+        } else {
+          if (e instanceof util.QTapError) {
+            e.qtapClient = {
+              browser: browserFn.displayName,
+              testFile: this.testFile
+            };
+          }
+          throw e;
+        }
+      }
+    }
+
+    await this.getClientResult(browserPromise);
+  }
 
+  /**
+   * Launch a browser once and throw if it takes too long to connect.
+   *
+   * @param {Function} browserFn
+   * @param {Object} browser
+   * @param {Object<string,AbortSignal>} signals
+   */
+  async launchBrowserAttempt (browserFn, browser, signals) {
     const proxyBase = this.getProxyBase();
     // Serve the a test file from URL that looks like the original path when possible.
     //
@@ -402,97 +478,63 @@ class ControlServer {
     // (e.g. www.mysite.test/mysite/). That test case depends on the real path.
     // https://github.com/WordPress/wordpress-develop/blob/6.7.1/tests/qunit/wp-admin/js/password-strength-meter.js#L100
     const tmpUrl = new URL(this.testFile + this.testFileQueryString, proxyBase);
-    tmpUrl.searchParams.set('qtap_clientId', clientId);
+    tmpUrl.searchParams.set('qtap_clientId', browser.clientId);
     const url = proxyBase + tmpUrl.pathname + tmpUrl.search;
 
-    const maxTries = (browserFn.allowRetries === false || this.debugMode) ? 1 : 3;
-    let i = 1;
-    while (true) {
-      try {
-        const browserPromise = this.launchBrowserAttempt(browserFn, browserName, globalSignal, clientId, url, logger);
-        const result = await browserPromise;
-        logger.debug('event_clientresult', result);
-        this.eventbus.emit('clientresult', result);
-        return;
-      } catch (e) {
-        // Do not retry uncaught errors from browserFn or client-side bailout,
-        // which are expected to be deterministic. Only retry BrowserConnectTimeout.
-        if (i >= maxTries || !(e instanceof util.BrowserConnectTimeout)) {
-          if (e instanceof util.QTapError) {
-            e.qtapClient = {
-              browser: browserFn.displayName,
-              testFile: this.testFile
-            };
-          }
-          throw e;
-        }
+    const connectTimeoutTimer = setTimeout(() => {
+      const reason = `Browser did not start within ${this.connectTimeout}s`;
+      this.launchingBrowsers.delete(browser.clientId);
+      browser.stop(new util.BrowserConnectTimeout(reason));
+      browser.logger.warning('browser_connect_timeout', reason);
+    }, this.connectTimeout * 1000);
+
+    this.on('clientonline', (event) => {
+      if (event.clientId === browser.clientId) {
+        browser.logger.debug('browser_connected', `${browserFn.getDisplayName()} connected! Serving test file.`);
+        this.launchingBrowsers.delete(browser.clientId);
+        clearTimeout(connectTimeoutTimer);
+      }
+    });
+
+    this.launchingBrowsers.add(browser.clientId);
+    browser.logger.debug('browser_launch_call');
+
+    try {
+      await browserFn(url, signals, browser.logger, this.debugMode);
 
-        i++;
-        logger.debug('browser_connect_retry', `Retrying, attempt ${i} of ${maxTries}`);
+      browser.logger.debug('browser_launch_exit');
+    } catch (/** @type {Error|Object|string} */ e) {
+      // Silence any errors from browserFn that happen after we called browser.stop().
+      if (signals.browser.aborted) {
+        browser.logger.debug('browser_launch_stopped', String(e.cause || e));
+      } else {
+        browser.logger.warning('browser_launch_error', e);
+        throw e;
       }
     }
-  }
 
-  async launchBrowserAttempt (browserFn, browserName, globalSignal, clientId, url, logger) {
-    const controller = new AbortController();
-
-    const signals = {
-      // NOTE: The browser signal tracks both "browser" and "global" controllers,
-      // so that if qtap.run() bails out (e.g. uncaught error from a reporter, or
-      // test server fails in fetchTestFile due to file not found), and if for
-      // some reason the natural shutdown fails (i.e. we don't call
-      // server.stopBrowsers or don't await browerPromise), then we have one
-      // last chance during shared_cleanup to stop dangling browser processes.
-      browser: AbortSignal.any([controller.signal, globalSignal]),
-      global: globalSignal
-    };
-    if (this.debugMode) {
-      // Replace with a dummy signal that we never invoke
-      //
-      // TODO: Refactor reporting and process mgmt so that results are reported
-      // on the CLI as normal. Right now, once the test finishes, the CLI doesn't
-      // report it because it waits to report until the browser exits. We need
-      // to create a way to keep report the results yet keep the process open.
-      signals.browser = (new AbortController()).signal;
-      signals.browser.addEventListener('abort', () => {
-        logger.warning('browser_signal_debugging', 'Keeping browser open for debugging');
-      });
+    if (signals.browser.aborted) {
+      // Throw BrowserConnectTimeout for retry purposes.
+      throw signals.browser.reason;
     }
+  }
 
+  /**
+   * Await a browser process and consume its results.
+   *
+   * @param {Function} browserFn
+   * @param {Object} browser
+   * @param {Object<string,AbortSignal>} signals
+   */
+  async getClientResult (browserPromise, browser, signals, clientId, url, logger) {
     let clientIdleTimer;
 
-    const browser = {
-      clientId,
-      logger,
-      clientIdleActive: null,
-      browserName,
-      getDisplayName () {
-        return browserFn.getDisplayName();
-      },
-      /**
-       * Reasons to stop a browser, whichever comes first:
-       * 1. tap-finished (client has sent us the test results).
-       * 2. tap-parser 'bailout' event (client knows it crashed).
-       * 3. timeout (client didn't connect, client idle and presumed lost, or a silent crash).
-       *
-       * @param {any} reason
-       */
-      stop: async (reason) => {
-        if (!this.browsers.has(clientId)) {
-          // Ignore any duplicate or late reasons to stop
-          return;
-        }
-
-        clearTimeout(clientIdleTimer);
-        this.browsers.delete(clientId);
-        controller.abort(reason);
-      }
-    };
-
     let result;
     const tapParser = tapFinished({ wait: 0 }, (finalResult) => {
+      clearTimeout(clientIdleTimer);
+
       result = {
-        clientId,
+        clientId: browser.clientId,
         ok: finalResult.ok,
         total: finalResult.count,
         // avoid precomputed `finalResult.todo` because that
@@ -557,16 +599,8 @@ class ControlServer {
     // Node.js/V8 natively allocating many timers when processing large batches of test results.
     // Instead, merely store performance.now() and check that periodically.
     const TIMEOUT_CHECK_MS = 100;
-    const browserStart = performance.now();
     const qtapCheckTimeout = () => {
-      if (!browser.clientIdleActive) {
-        if ((performance.now() - browserStart) > (this.connectTimeout * 1000)) {
-          const reason = `Browser did not start within ${this.connectTimeout}s`;
-          logger.warning('browser_connect_timeout', reason);
-          browser.stop(new util.BrowserConnectTimeout(reason));
-          return;
-        }
-      } else {
+      if (browser.connected) {
         if ((performance.now() - browser.clientIdleActive) > (this.idleTimeout * 1000)) {
           const reason = `Browser idle for ${this.idleTimeout}s`;
           logger.warning('browser_idle_timeout', reason);
@@ -579,12 +613,10 @@ class ControlServer {
     clientIdleTimer = setTimeout(qtapCheckTimeout, TIMEOUT_CHECK_MS);
 
     try {
-      logger.debug('browser_launch_call');
-
-      await browserFn(url, signals, logger, this.debugMode);
+      await browserPromise;
 
       // Usually browserFn() will return because we asked via browser.stop(), e.g. tests finished,
-      // bailed, or timed out. In case the browser ended by itself, we call browser.stop() here,
+      // or timed out. In case the browser ended by itself, we call browser.stop() here,
       // so that if we didn't called it before, this will report an error.
       // Also, this ensures the signal can clean up any resources created by browserFn.
       logger.debug('browser_launch_exit');
@@ -606,6 +638,8 @@ class ControlServer {
     }
 
     return result;
+        logger.debug('event_clientresult', result);
+        this.eventbus.emit('clientresult', result);
   }
 
   /** @return {string} */

src/tap-finished.js

@@ -28,7 +28,18 @@
  *   Upgrade from tap-parser@5 to tap-parser@18, so that QTap doesn't pull in the
  *   35 dependencies that tap-parser@5 carried to support old Node.js versions.
  *
- * - Consider bailout as finished to avoid a hanging process.
+ * - Add bailout as 'finished' trigger, to avoid a hanging process.
+ *
+ * - Fix hang when calling p.end() to close unfinished stream,
+ *   due to unreachable inner 'complete' event when calling finish()
+ *   from the outer 'complete' event (no memory, not fired twice).
+ *
+ *   This appears to be caused by [1] when switching finish() from `cb(p.results)`,
+ *   to `p.on('complete', cb)`.
+ *
+ * - Fix duplicate p.end() when wait=0 due to missing !ended check.
+ *
+ * [1]: https://github.com/tapjs/tap-finished/commit/35b653d778a4f387c269f6dfbe95066455636410 
  */
 'use strict';
 
@@ -60,7 +71,7 @@ export default function tapFinished (opts, cb) {
     });
     if (opts.wait && !ended) {
       setTimeout(function () { p.end(); }, opts.wait);
-    } else { p.end(); }
+    } else if (!ended) { p.end(); }
   }
 
   function check () {
@@ -81,14 +92,15 @@ export default function tapFinished (opts, cb) {
     check();
   });
 
-  p.on('complete', function () {
+  p.on('bailout', function () {
     if (finished) { return; }
     finish();
   });
 
-  p.on('bailout', function () {
+  p.on('complete', function () {
     if (finished) { return; }
-    finish();
+    finished = true;
+    cb(p.results);
   });
 
   return p;