Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[no ticket][risk=no] Puppeteer test log improvement #4660

Merged
merged 17 commits into from
Mar 10, 2021
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);
Comment on lines -40 to -42
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

redundant. saving screenshot and html is done in
handleTestEvent

}
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
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

setting bail prevents test log write to file. Alternative is implemented in PuppeteerCustomEnvironment's handleTestEvent.

"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',
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

First time seeing this list. This should have a comment about why you would add something to this list.

Also, page-visits does not have a /, this seems like a bug

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done.

'/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) => {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FYI: Somehow logging of console pageerror and error are not working. I don't have a solution at this time.

console.error
      PAGEERROR: "Edit Workspace | [Test] All of Us Researcher Workbench"
      Error: Object
      Object

      219 |     const title = await getPageTitle();
      220 |     try {
    > 221 |       console.error(`PAGEERROR: "${title}"\n${error.toString()}\n${error.message}\n${error.stack}`);
          |               ^
      222 |       console.log('');
      223 |     } catch (err) {
      224 |       console.error(`❗ "${title}"\nPage exception occurred when getting pageerror.\n${err}`);

      at jest.test-setup.ts:221:15

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.")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shouldn't this just be an console error? Is there no situation where you'd want to run like this?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In "verbose": true mode, console logs are not saved by jest internally, so logs won't be available to onTestResult function. I want to stop the test if it was changed. IMO, there isn't any good reason to use verbose: true.

}
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
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why? Aren't you in a JS file anyway?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

tslint is checking all files (.ts, .js) because tsconfig.json is config with "inclue": ["/*"]. tslint is soon to be replaced by eslint. We can safely ignore this "bug" at this time.

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' }),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice

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",
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ansi code makes test log harder to read.

"_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"
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

winston: timestamp and saving to file.

}
}
Loading