Skip to content

Commit

Permalink
test: pass logger to smokehouse runners to get log even if timed out
Browse files Browse the repository at this point in the history
  • Loading branch information
connorjclark committed Sep 3, 2024
1 parent 21e4444 commit 80dadcf
Show file tree
Hide file tree
Showing 5 changed files with 42 additions and 31 deletions.
19 changes: 10 additions & 9 deletions cli/test/smokehouse/lighthouse-runners/bundle.js
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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,
Expand All @@ -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;
Expand All @@ -142,7 +144,6 @@ async function runLighthouse(url, config, testRunnerOptions = {}) {
return {
lhr: result.lhr,
artifacts,
log,
};
}

Expand Down
31 changes: 16 additions & 15 deletions cli/test/smokehouse/lighthouse-runners/cli.js
Original file line number Diff line number Diff line change
Expand Up @@ -28,15 +28,16 @@ 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}));
}
Expand All @@ -46,12 +47,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/`;
Expand All @@ -78,7 +80,7 @@ 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}`);
logger.log(`${log.dim}$ ${command} ${args.join(' ')} ${log.reset}`);

/** @type {{stdout: string, stderr: string, code?: number}} */
let execResult;
Expand All @@ -91,16 +93,16 @@ async function internalRun(url, tmpPath, config, options) {

const exitCode = execResult.code || 0;
if (isDebug) {
localConsole.log(`exit code ${exitCode}`);
localConsole.log(`STDOUT: ${execResult.stdout}`);
localConsole.log(`STDERR: ${execResult.stderr}`);
logger.log(`exit code ${exitCode}`);
logger.log(`STDOUT: ${execResult.stdout}`);
logger.log(`STDERR: ${execResult.stderr}`);
}

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());
logger.getLog());
}

/** @type {LH.Result} */
Expand All @@ -109,21 +111,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(),
};
}

Expand Down
13 changes: 8 additions & 5 deletions cli/test/smokehouse/lighthouse-runners/devtools.js
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
7 changes: 6 additions & 1 deletion cli/test/smokehouse/smokehouse.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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) {
Expand All @@ -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.
}

Expand Down
3 changes: 2 additions & 1 deletion types/internal/smokehouse.d.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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. */
Expand Down

0 comments on commit 80dadcf

Please sign in to comment.