Skip to content

Commit

Permalink
[no ticket][risk=no] Puppeteer test log improvement (#4660)
Browse files Browse the repository at this point in the history
* wip

* wip

* save jest log to file

* winston logger

* write individual test log

* save

* remove jest bail

* remove @jest npm packages

* jest bail alternative

* ci retest

* redundant --no-color option

* consistent test report title

* PR feedback

* create winston file logger in jest-reporter.js

* revert last commit

* failed test log file name is FAILED

* remove bail alternative bc it's not working for parallism
  • Loading branch information
aweng98 authored Mar 10, 2021
1 parent b17ca83 commit ac0cd0a
Show file tree
Hide file tree
Showing 8 changed files with 368 additions and 75 deletions.
12 changes: 2 additions & 10 deletions e2e/app/page/authenticated-page.ts
Original file line number Diff line number Diff line change
Expand Up @@ -3,11 +3,9 @@ import {PageUrl} from 'app/text-labels';
import BasePage from 'app/page/base-page';
import {getPropValue} from 'utils/element-utils';
import HelpTipsSidebar from 'app/component/help-tips-sidebar';
import {savePageToFile, takeScreenshot} from 'utils/save-file-utils';

const signedInIndicator = 'app-signed-in';


/**
* AuthenticatedPage represents the base page for any AoU page after user has successfully logged in (aka authenticated).
* This is the base page for all AoU pages to extends from.
Expand All @@ -33,14 +31,8 @@ export default abstract class AuthenticatedPage extends BasePage {
* Wait until current page is loaded and without spinners spinning.
*/
async waitForLoad(): Promise<this> {
try {
await this.isSignedIn();
await this.isLoaded();
} catch (err) {
await savePageToFile(this.page);
await takeScreenshot(this.page);
throw (err);
}
await this.isSignedIn();
await this.isLoaded();
await this.closeHelpSidebarIfOpen();
return this;
}
Expand Down
18 changes: 14 additions & 4 deletions e2e/jest.config.js
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,6 @@ const { TEST_MODE } = process.env;

module.exports = {
"verbose": false,
"bail": 1, // Stop running tests after `n` failures
"preset": "jest-puppeteer",
"testTimeout": 1200000,
"testRunner": "jest-circus/runner",
Expand All @@ -17,14 +16,25 @@ module.exports = {
],
"reporters": [
"default",
"jest-junit",
[
"jest-stare", {
["jest-stare", {
"resultDir": "logs",
"resultJson": "test-results.json",
"reportTitle": "AoU integration tests",
"report": false
}
],
["jest-junit", {
outputDirectory: "./logs/junit",
outputName: "test-results.xml",
classNameTemplate: "{filepath}",
suiteNameTemplate: "{filepath}",
suiteName: "AoU integration tests"
}
],
["<rootDir>/libs/jest-reporter.js", {
"outputdir": "logs/jest",
"filename": "test-results-summary.json"
}
]
],
"transform": {
Expand Down
67 changes: 38 additions & 29 deletions e2e/jest.test-setup.ts
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
import { logger } from 'libs/logger';
import * as fp from 'lodash/fp';
import {Request} from 'puppeteer';
import {JSHandle, Request} from 'puppeteer';
const userAgent = 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/80.0.3987.149 Safari/537.36';

/**
Expand All @@ -17,14 +18,19 @@ beforeEach(async () => {
page.setDefaultNavigationTimeout(60000); // Puppeteer default timeout is 30 seconds.
await page.setRequestInterception(true);

const getTitle = async () => {
const getPageTitle = async () => {
return await page.$eval('title', title => {
return title.textContent;
}).catch(() => {return 'getTitle() func failed'});
}).catch(() => {return 'getPageTitle() func failed'});
}

const describeJsHandle = async (jsHandle) => {
const describeJsHandle = async (jsHandle: JSHandle): Promise<string> => {
return jsHandle.executionContext().evaluate(obj => {
// Get error message if obj is an error. Error is not serializeable.
if (obj instanceof Error) {
return obj.message;
}
// Return JSON value of the argument or `undefined`.
return obj.toString();
}, jsHandle);
}
Expand Down Expand Up @@ -70,18 +76,20 @@ beforeEach(async () => {
: null;
}

// Api response won't be logged.
// Disable logging of API response body in test log to make log less cluttered.
// Following API response body are not helpful for error troubleshooting.
const shouldSkipApiResponseBody = (request: Request): boolean => {
const filters = [
'/readonly',
'/chartinfo/',
'page-visits',
'/page-visits',
'/generateCode/',
'/criteria/CONDITION/search/',
'/criteria/',
'/cdrVersions',
'/config',
'/user-recent-workspaces',
'/user-recent-resources',
'/profile'
];
return filters.some((partialUrl) => request && request.url().includes(partialUrl));
Expand Down Expand Up @@ -117,8 +125,8 @@ beforeEach(async () => {
const response = request.response();
const failureText = request.failure() !== null ? stringifyData(request.failure().errorText) : '';
const responseText = stringifyData(await getResponseText(request));
console.error('❗ Request failed: ' +
`${response.status()} ${request.method()} ${request.url()}\n${responseText}\n${failureText}`);
logger.log('error', 'Request failed: %s %s %s\n%s %s',
response.status(), request.method(), request.url(), responseText, failureText);
}

const transformResponseBody = async (request: Request): Promise<string> => {
Expand All @@ -128,7 +136,7 @@ beforeEach(async () => {
// truncate long response. get first two workspace details.
responseText = fp.isEmpty(JSON.parse(responseText).items)
? responseText
: 'truncated...\n' + JSON.stringify(JSON.parse(responseText).items.slice(0, 2), null, 2);
: `truncated...\n${JSON.stringify(JSON.parse(responseText).items.slice(0, 1), null, 2)}`;
}
return responseText;
}
Expand All @@ -141,8 +149,9 @@ beforeEach(async () => {
// New request initiated
page.on('request', (request) => {
if (isWorkbenchRequest(request)) {
console.debug('❗ Request issued: ' +
`${request.method()} ${request.url()}\n${getRequestData(request)}`);
const requestBody = getRequestData(request);
const body = requestBody.length === 0 ? '' : `\n${requestBody}`;
logger.log('info', 'Request issued: %s %s %s', request.method(), request.url(), body);
}
try {
request.continue();
Expand All @@ -166,17 +175,16 @@ beforeEach(async () => {
if (isApiFailure(request)) {
await logError(request);
} else {
if (shouldSkipApiResponseBody(request)) {
console.debug(`❗ Request finished: ${status} ${method} ${url}`);
} else {
console.debug('❗ Request finished: ' +
`${status} ${method} ${url}\n${await transformResponseBody(request)}`);
let text = `Request finished: ${status} ${method} ${url}`;
if (!shouldSkipApiResponseBody(request)) {
text = `${text}\n${await transformResponseBody(request)}`;
}
logger.log('info', text);
}
}
} catch (err) {
// Try find out what the request was
console.error(`${err}\n${status} ${method} ${url}`);
logger.log('error', '%s %s %s\n%s', status, method, url, err);
}
try {
await request.continue();
Expand All @@ -186,33 +194,34 @@ beforeEach(async () => {
});

page.on('console', async (message) => {
if (!message.args().length) {
return;
}
const title = await getTitle();
if (!message.args().length) return;
const title = await getPageTitle();
try {
const args = await Promise.all(message.args().map(a => describeJsHandle(a)));
console[message.type() === 'warning' ? 'warn' : message.type()](`❗ ${title}\n${message.text()}`, ...args);
console[message.type() === 'warning' ? 'warn' : message.type()](`Page console: "${title}"\n`, ...args);
console.log('');
} catch (err) {
console.error(`❗ ${title}\nException occurred when getting console message.\n${err}\n${message.text()}`);
console.error(`❗ "${title}"\nException occurred when getting page console message.\n${err}\n${message.text()}`);
}
});

page.on('error', async (error) => {
const title = await getTitle();
const title = await getPageTitle();
try {
console.error(`❗ ${title}\nError message: ${error.message}\nStack: ${error.stack}`);
console.error(`PAGE ERROR: "${title}"\n${error.toString()}\n${error.message}\n${error.stack}`);
console.log('');
} catch (err) {
console.error(`❗ ${title}\nException occurred when getting error.\n${err}`);
console.error(`❗ "${title}"\nException occurred when getting page error.\n${err}`);
}
});

page.on('pageerror', async (error) => {
const title = await getTitle();
const title = await getPageTitle();
try {
console.error(`❗ ${title}\nPage error message: ${error.message}\nStack: ${error.stack}`);
console.error(`PAGEERROR: "${title}"\n${error.toString()}\n${error.message}\n${error.stack}`);
console.log('');
} catch (err) {
console.error(`❗ ${title}\nPage exception occurred when getting pageerror.\n${err}`);
console.error(`❗ "${title}"\nPage exception occurred when getting pageerror.\n${err}`);
}
})

Expand Down
94 changes: 94 additions & 0 deletions e2e/libs/jest-reporter.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,94 @@
const fs = require('fs-extra');
const path = require('path');
const winston = require("winston");

module.exports = class JestReporter {

constructor(globalConfig, options) {
if (globalConfig.verbose === true) {
throw Error("Verbose must be false or Console messages won't be available.")
}
this._globalConfig = globalConfig;
this._options = options;
this.logDir = this._options.outputdir || 'logs/jest';
this.summaryFile = this._options.filename || 'test-results-summary.json';
}

onTestStart(test) {
const time = new Date().toLocaleTimeString();
console.info(`Running ${path.parse(test.path).name} at ${time}`);
}

// @ts-ignore
onTestResult(testRunConfig, testResult, runResults) {
const testName = path.parse(testResult.testFilePath).name;
let testLogName = `${this.logDir}/${testName}.log`;
testResult.testResults.forEach((result) => {
const status = result.status;
if (status === 'failed') {
testLogName = `${this.logDir}/${testName}-FAILED.log`;
}
});

const fileLogger = winston.createLogger({
level: process.env.LOG_LEVEL || "info",
format: winston.format.combine(
winston.format.splat(),
winston.format.printf( (info) => {return `${info.message}`; })
),
transports: [new winston.transports.File({
filename: testLogName,
options: { flags: 'w' },
handleExceptions: true,
})
],
exitOnError: false
});

// Read jest console messages and save to a log file.
// Get all console logs.
if (testResult.console && testResult.console.length > 0) {
testResult.console.forEach((log) => {
fileLogger.info(log.message);
});
}

// Get failure messages.
testResult.testResults.forEach((result) => {
fileLogger.info('----------------------------------------');
fileLogger.log('info', 'test name: %s', result.title);
fileLogger.log('info', 'status: %s', result.status);
// Get failure message.
if (result.failureMessages) {
const failure = result.failureMessages;
fileLogger.log('info', 'failure: %s', failure);
}
});
console.log(`Save test log: ${testLogName}`);
}

// @ts-ignore
onRunComplete(test, runResults) {
runResults.testResults.forEach(suite => {
const testFilePath = suite.testFilePath.split('e2e/')[1];
const failedTests = [];
suite.testResults.forEach(result => {
if (result.status === 'failed') {
failedTests.push(`yarn test ${testFilePath}`);
}
});
if (failedTests.length > 0) {
console.info(`**** To rerun failed tests:\n ${failedTests}`);
}
});

// Save test results to a file.
if (!fs.existsSync(this.logDir)) {
fs.mkdirSync(this.logDir);
}
fs.writeFileSync(`${this.logDir}/${this.summaryFile}`, JSON.stringify(runResults, null, 2));
console.info(`Save tests results summary file: ${this.logDir}/${this.summaryFile}`);
return runResults;
}

}
21 changes: 21 additions & 0 deletions e2e/libs/logger.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,21 @@
const winston = require('winston');
const { createLogger, format } = winston;

// Log to Console.
const logger = createLogger({
level: process.env.LOG_LEVEL || "info",
format: format.combine(
format.prettyPrint(),
format.splat(),
format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),
format.printf( (info) => {
return `${info.level.toUpperCase()}: [${info.timestamp}] - ${info.message}`;
}),
),
transports: [
new winston.transports.Console({ handleExceptions: true}),
],
exitOnError: false
});

module.exports = { logger };
18 changes: 7 additions & 11 deletions e2e/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -7,8 +7,8 @@
"license": "BSD",
"scripts": {
"impersonate-test-user": "env-cmd -x ../api/project.rb generate-impersonated-user-token --impersonated-user=\\$USER_NAME --output-token-filename=../e2e/puppeteer-access-token.txt",
"_test": "yarn impersonate-test-user && jest",
"_test:debugTest": "yarn impersonate-test-user && node --inspect-brk node_modules/.bin/jest",
"_test": "yarn impersonate-test-user && jest --no-color",
"_test:debugTest": "yarn impersonate-test-user && node --inspect-brk node_modules/.bin/jest --no-color",
"test": "cross-env yarn _test --maxWorkers=5",
"test:debugTest": "cross-env PUPPETEER_HEADLESS=false DEBUG=true yarn _test:debugTest",
"test:debug": "cross-env PUPPETEER_HEADLESS=false DEBUG=true yarn _test --detectOpenHandles",
Expand All @@ -18,7 +18,7 @@
"test-local-devup:debug": "cross-env WORKBENCH_ENV=local PUPPETEER_HEADLESS=false DEBUG=true node --inspect-brk node_modules/.bin/jest --maxWorkers=3",
"test-staging": "cross-env WORKBENCH_ENV=staging yarn _test --maxWorkers=3",
"test-staging:debug": "cross-env WORKBENCH_ENV=staging PUPPETEER_HEADLESS=false DEBUG=true yarn _test --maxWorkers=1",
"test:ci": "yarn _test --no-color --ci --maxWorkers=2 --forceExit",
"test:ci": "yarn _test --ci --maxWorkers=2 --forceExit",
"test:ci:debug": "yarn _test --ci --debug --maxWorkers=1 --bail 1",
"test-nightly": "cross-env TEST_MODE=nightly-integration yarn _test --maxWorkers=1",
"test-nightly-local-devup": "cross-env TEST_MODE=nightly-integration yarn jest --maxWorkers=1",
Expand All @@ -38,16 +38,11 @@
"engines": {
"node": ">= 10.0.0"
},
"jest-junit": {
"outputDirectory": "./logs",
"outputName": "test-results.xml",
"classNameTemplate": "{filepath}",
"suiteNameTemplate": "{filepath}"
},
"dependencies": {},
"devDependencies": {
"@types/expect-puppeteer": "4.4.5",
"@types/faker": "5.1.5",
"@types/fs-extra": "^9.0.8",
"@types/jest": "26.0.16",
"@types/jest-environment-puppeteer": "4.4.0",
"@types/lodash": "4.14.165",
Expand All @@ -61,7 +56,7 @@
"jest": "26.6.3",
"jest-circus": "26.6.3",
"jest-config": "26.6.3",
"jest-junit": "^11.0.1",
"jest-junit": "^12.0.0",
"jest-puppeteer": "4.4.0",
"jest-stare": "2.2.0",
"lodash": "4.17.20",
Expand All @@ -74,6 +69,7 @@
"tslint-config-prettier": "1.18.0",
"tslint-eslint-rules": "5.4.0",
"tslint-microsoft-contrib": "6.2.0",
"typescript": "4.1.2"
"typescript": "4.1.2",
"winston": "^3.3.3"
}
}
Loading

0 comments on commit ac0cd0a

Please sign in to comment.