From ba1a46c8816eb7028b7b9301e250b614d133f83f Mon Sep 17 00:00:00 2001 From: Connor Clark Date: Wed, 4 Sep 2024 16:50:02 -0700 Subject: [PATCH] tests: pass logger to smokehouse runners to get log even on timeout (#16175) --- .../smokehouse/lighthouse-runners/bundle.js | 19 +++--- cli/test/smokehouse/lighthouse-runners/cli.js | 58 +++++++++---------- .../smokehouse/lighthouse-runners/devtools.js | 13 +++-- cli/test/smokehouse/smokehouse.js | 7 ++- types/internal/smokehouse.d.ts | 3 +- 5 files changed, 52 insertions(+), 48 deletions(-) diff --git a/cli/test/smokehouse/lighthouse-runners/bundle.js b/cli/test/smokehouse/lighthouse-runners/bundle.js index b8ca0be49387..e10fc446c789 100644 --- a/cli/test/smokehouse/lighthouse-runners/bundle.js +++ b/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, }; } diff --git a/cli/test/smokehouse/lighthouse-runners/cli.js b/cli/test/smokehouse/lighthouse-runners/cli.js index 14be8db8f59e..aa5df6c04442 100644 --- a/cli/test/smokehouse/lighthouse-runners/cli.js +++ b/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} */ + 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(), }; } diff --git a/cli/test/smokehouse/lighthouse-runners/devtools.js b/cli/test/smokehouse/lighthouse-runners/devtools.js index bb57949e8a7d..e287417b96ac 100644 --- a/cli/test/smokehouse/lighthouse-runners/devtools.js +++ b/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 { diff --git a/cli/test/smokehouse/smokehouse.js b/cli/test/smokehouse/smokehouse.js index 0a329abdaac8..7a6cf32835f3 100644 --- a/cli/test/smokehouse/smokehouse.js +++ b/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. } diff --git a/types/internal/smokehouse.d.ts b/types/internal/smokehouse.d.ts index a0e5c8f0b3dc..66c65ea3c6f8 100644 --- a/types/internal/smokehouse.d.ts +++ b/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} 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. */