tests: pass logger to smokehouse runners to get log even on timeout (#…

…16175)

cli/test/smokehouse/lighthouse-runners/bundle.js

@@ -21,6 +21,7 @@ import * as ChromeLauncher from 'chrome-launcher';
 
 import {LH_ROOT} from '../../../../shared/root.js';
 import {loadArtifacts, saveArtifacts} from '../../../../core/lib/asset-saver.js';
+import {LocalConsole} from '../lib/local-console.js';
 
 // This runs only in the worker. The rest runs on the main thread.
 if (!isMainThread && parentPort) {
@@ -105,12 +106,13 @@ async function runBundledLighthouse(url, config, testRunnerOptions) {
  * Launch Chrome and do a full Lighthouse run via the Lighthouse DevTools bundle.
  * @param {string} url
  * @param {LH.Config=} config
+ * @param {LocalConsole=} logger
  * @param {Smokehouse.SmokehouseOptions['testRunnerOptions']=} testRunnerOptions
- * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts, log: string}>}
+ * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts}>}
  */
-async function runLighthouse(url, config, testRunnerOptions = {}) {
-  /** @type {string[]} */
-  const logs = [];
+async function runLighthouse(url, config, logger, testRunnerOptions = {}) {
+  logger = logger || new LocalConsole();
+
   const worker = new Worker(new URL(import.meta.url), {
     stdout: true,
     stderr: true,
@@ -119,16 +121,16 @@ async function runLighthouse(url, config, testRunnerOptions = {}) {
   worker.stdout.setEncoding('utf8');
   worker.stderr.setEncoding('utf8');
   worker.stdout.addListener('data', (data) => {
-    logs.push(`[STDOUT] ${data}`);
+    logger.log(`[STDOUT] ${data}`);
   });
   worker.stderr.addListener('data', (data) => {
-    logs.push(`[STDERR] ${data}`);
+    logger.log(`[STDERR] ${data}`);
   });
   const [workerResponse] = await once(worker, 'message');
-  const log = logs.join('') + '\n';
 
   if (workerResponse.type === 'error') {
-    throw new Error(`Worker returned an error: ${workerResponse.value}\nLog:\n${log}`);
+    const log = logger.getLog();
+    throw new Error(`Worker returned an error: ${workerResponse.value}\nLog:\n${log}\n`);
   }
 
   const result = workerResponse.value;
@@ -142,7 +144,6 @@ async function runLighthouse(url, config, testRunnerOptions = {}) {
   return {
     lhr: result.lhr,
     artifacts,
-    log,
   };
 }
 

cli/test/smokehouse/lighthouse-runners/cli.js

@@ -12,8 +12,7 @@
  */
 
 import {promises as fs} from 'fs';
-import {promisify} from 'util';
-import {execFile} from 'child_process';
+import {spawn} from 'child_process';
 
 import log from 'lighthouse-logger';
 
@@ -22,21 +21,20 @@ import {LocalConsole} from '../lib/local-console.js';
 import {ChildProcessError} from '../lib/child-process-error.js';
 import {LH_ROOT} from '../../../../shared/root.js';
 
-const execFileAsync = promisify(execFile);
-
 /**
  * Launch Chrome and do a full Lighthouse run via the Lighthouse CLI.
  * @param {string} url
  * @param {LH.Config=} config
+ * @param {LocalConsole=} logger
  * @param {Smokehouse.SmokehouseOptions['testRunnerOptions']=} testRunnerOptions
- * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts, log: string}>}
+ * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts}>}
  */
-async function runLighthouse(url, config, testRunnerOptions = {}) {
+async function runLighthouse(url, config, logger, testRunnerOptions = {}) {
   const {isDebug} = testRunnerOptions;
   const tmpDir = `${LH_ROOT}/.tmp/smokehouse`;
   await fs.mkdir(tmpDir, {recursive: true});
   const tmpPath = await fs.mkdtemp(`${tmpDir}/smokehouse-`);
-  return internalRun(url, tmpPath, config, testRunnerOptions)
+  return internalRun(url, tmpPath, config, logger, testRunnerOptions)
     // Wait for internalRun() before removing scratch directory.
     .finally(() => !isDebug && fs.rm(tmpPath, {recursive: true, force: true}));
 }
@@ -46,12 +44,13 @@ async function runLighthouse(url, config, testRunnerOptions = {}) {
  * @param {string} url
  * @param {string} tmpPath
  * @param {LH.Config=} config
+ * @param {LocalConsole=} logger
  * @param {Smokehouse.SmokehouseOptions['testRunnerOptions']=} options
- * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts, log: string}>}
+ * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts}>}
  */
-async function internalRun(url, tmpPath, config, options) {
+async function internalRun(url, tmpPath, config, logger, options) {
   const {isDebug, headless} = options || {};
-  const localConsole = new LocalConsole();
+  logger = logger || new LocalConsole();
 
   const outputPath = `${tmpPath}/smokehouse.report.json`;
   const artifactsDirectory = `${tmpPath}/artifacts/`;
@@ -78,29 +77,25 @@ async function internalRun(url, tmpPath, config, options) {
 
   const command = 'node';
   const env = {...process.env, NODE_ENV: 'test'};
-  localConsole.log(`${log.dim}$ ${command} ${args.join(' ')} ${log.reset}`);
-
-  /** @type {{stdout: string, stderr: string, code?: number}} */
-  let execResult;
-  try {
-    execResult = await execFileAsync(command, args, {env});
-  } catch (e) {
-    // exec-thrown errors have stdout, stderr, and exit code from child process.
-    execResult = e;
-  }
-
-  const exitCode = execResult.code || 0;
-  if (isDebug) {
-    localConsole.log(`exit code ${exitCode}`);
-    localConsole.log(`STDOUT: ${execResult.stdout}`);
-    localConsole.log(`STDERR: ${execResult.stderr}`);
+  logger.log(`${log.dim}$ ${command} ${args.join(' ')} ${log.reset}`);
+
+  const cp = spawn(command, args, {env});
+  cp.stdout.on('data', data => logger.log(`[STDOUT] ${data.toString().trim()}`));
+  cp.stderr.on('data', data => logger.log(`[STDERR] ${data.toString().trim()}`));
+  /** @type {Promise<number|null>} */
+  const cpPromise = new Promise((resolve, reject) => {
+    cp.addListener('exit', resolve);
+    cp.addListener('error', reject);
+  });
+  const exitCode = await cpPromise;
+  if (exitCode) {
+    logger.log(`exit code ${exitCode}`);
   }
 
   try {
     await fs.access(outputPath);
   } catch (e) {
-    throw new ChildProcessError(`Lighthouse run failed to produce a report and exited with ${exitCode}.`, // eslint-disable-line max-len
-        localConsole.getLog());
+    throw new ChildProcessError(`Lighthouse run failed to produce a report.`, logger.getLog());
   }
 
   /** @type {LH.Result} */
@@ -109,21 +104,20 @@ async function internalRun(url, tmpPath, config, options) {
 
   // Output has been established as existing, so can log for debug.
   if (isDebug) {
-    localConsole.log(`LHR output available at: ${outputPath}`);
-    localConsole.log(`Artifacts avaiable in: ${artifactsDirectory}`);
+    logger.log(`LHR output available at: ${outputPath}`);
+    logger.log(`Artifacts avaiable in: ${artifactsDirectory}`);
   }
 
   // There should either be both an error exitCode and a lhr.runtimeError or neither.
   if (Boolean(exitCode) !== Boolean(lhr.runtimeError)) {
     const runtimeErrorCode = lhr.runtimeError?.code;
     throw new ChildProcessError(`Lighthouse did not exit with an error correctly, exiting with ${exitCode} but with runtimeError '${runtimeErrorCode}'`, // eslint-disable-line max-len
-        localConsole.getLog());
+      logger.getLog());
   }
 
   return {
     lhr,
     artifacts,
-    log: localConsole.getLog(),
   };
 }
 

cli/test/smokehouse/lighthouse-runners/devtools.js

@@ -40,21 +40,24 @@ async function setup() {
  * CHROME_PATH determines which Chrome is used–otherwise the default is puppeteer's chrome binary.
  * @param {string} url
  * @param {LH.Config=} config
+ * @param {import('../lib/local-console.js').LocalConsole=} logger
  * @param {Smokehouse.SmokehouseOptions['testRunnerOptions']=} testRunnerOptions
- * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts, log: string}>}
+ * @return {Promise<{lhr: LH.Result, artifacts: LH.Artifacts}>}
  */
-async function runLighthouse(url, config, testRunnerOptions) {
+async function runLighthouse(url, config, logger, testRunnerOptions) {
   const chromeFlags = [
     testRunnerOptions?.headless ? '--headless=new' : '',
     `--custom-devtools-frontend=file://${devtoolsDir}/out/LighthouseIntegration/gen/front_end`,
   ];
+  // TODO: `testUrlFromDevtools` should accept a logger, so we get some output even for time outs.
   const {lhr, artifacts, logs} = await testUrlFromDevtools(url, {
     config,
     chromeFlags,
   });
-
-  const log = logs.join('') + '\n';
-  return {lhr, artifacts, log};
+  if (logger) {
+    logger.log(logs.join('') + '\n');
+  }
+  return {lhr, artifacts};
 }
 
 export {

cli/test/smokehouse/smokehouse.js

@@ -161,6 +161,8 @@ async function runSmokeTest(smokeTestDefn, testOptions) {
       bufferedConsole.log(`  Retrying run (${i} out of ${retries} retries)…`);
     }
 
+    const logger = new LocalConsole();
+
     // Run Lighthouse.
     try {
       // Each individual runner has internal timeouts, but we've had bugs where
@@ -170,12 +172,13 @@ async function runSmokeTest(smokeTestDefn, testOptions) {
           reject(new Error('Timed out waiting for provided lighthouseRunner')), 1000 * 120);
       });
       const timedResult = await Promise.race([
-        lighthouseRunner(requestedUrl, config, testRunnerOptions),
+        lighthouseRunner(requestedUrl, config, logger, testRunnerOptions),
         timeoutPromise,
       ]);
       result = {
         ...timedResult,
         networkRequests: takeNetworkRequestUrls ? takeNetworkRequestUrls() : undefined,
+        log: logger.getLog(),
       };
 
       if (!result.lhr?.audits || !result.artifacts) {
@@ -188,6 +191,8 @@ async function runSmokeTest(smokeTestDefn, testOptions) {
       if (takeNetworkRequestUrls) takeNetworkRequestUrls();
 
       logChildProcessError(bufferedConsole, e);
+      bufferedConsole.log('Timed out. log from lighthouseRunner:');
+      bufferedConsole.log(logger.getLog());
       continue; // Retry, if possible.
     }
 

types/internal/smokehouse.d.ts

@@ -7,6 +7,7 @@
 import {Artifacts} from '../artifacts.js';
 import Config from '../config.js';
 import LHResult from '../lhr/lhr.js';
+import {LocalConsole} from '../../cli/test/smokehouse/lib/local-console.js';
 
 declare global {
   module Smokehouse {
@@ -53,7 +54,7 @@ declare global {
       {expectations: Smokehouse.ExpectedRunnerResult | Array<Smokehouse.ExpectedRunnerResult>}
 
     export type LighthouseRunner =
-      {runnerName?: string} & ((url: string, config?: Config, runnerOptions?: {isDebug?: boolean}) => Promise<{lhr: LHResult, artifacts: Artifacts, log: string}>);
+      {runnerName?: string} & ((url: string, config?: Config, logger?: LocalConsole, runnerOptions?: {isDebug?: boolean}) => Promise<{lhr: LHResult, artifacts: Artifacts}>);
 
     export interface SmokehouseOptions {
       /** Options to pass to the specific Lighthouse runner. */