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

aweng98 · 2021-03-07T00:32:32Z

Adding log timestamp and saving single test log file.

New test logs structure:

aweng98 · 2021-03-08T18:04:16Z

e2e/app/page/authenticated-page.ts

-      await savePageToFile(this.page);
-      await takeScreenshot(this.page);
-      throw (err);


redundant. saving screenshot and html is done in
handleTestEvent

aweng98 · 2021-03-08T18:05:33Z

e2e/jest.config.js

@@ -3,7 +3,6 @@ const { TEST_MODE } = process.env;

 module.exports = {
  "verbose": false,
-  "bail": 1,  // Stop running tests after `n` failures


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

aweng98 · 2021-03-08T18:07:14Z

e2e/puppeteer-custom-environment.ts

+    if (this.failedTest && event.name === 'test_start') {
+      event.test.mode = 'skip';
+    }
+    if (super.handleTestEvent) {
+      super.handleTestEvent(event, state)
+    }


Alternative to Jest bail.
#6527 comment

aweng98 · 2021-03-08T18:08:01Z

e2e/package.json

@@ -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"


winston: timestamp and saving to file.

aweng98 · 2021-03-08T18:08:49Z

e2e/package.json

@@ -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",


ansi code makes test log harder to read.

calbach

Looking good, thanks - a couple of questions on this

calbach · 2021-03-08T23:49:58Z

e2e/jest.test-setup.ts

@@ -82,6 +85,7 @@ beforeEach(async () => {
      '/cdrVersions',
      '/config',
      '/user-recent-workspaces',
+      '/user-recent-resources',


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

calbach · 2021-03-08T23:52:10Z

e2e/libs/jest-reporter.js

+    console.info(`Running ${path.parse(test.path).name} at ${time}`);
+  }
+
+  // @ts-ignore


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

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.

calbach · 2021-03-08T23:54:45Z

e2e/libs/jest-reporter.js

+    });
+
+    // Save test results to a file.
+    if (!fs.existsSync(this.logDir)) fs.mkdirSync(this.logDir);


nit: generally we avoid 1 line if statements like this in the codebase, or without brackets

calbach · 2021-03-08T23:56:38Z

e2e/libs/jest-reporter.js

+
+  constructor(globalConfig, options) {
+    if (globalConfig.verbose === true) {
+      throw Error("Verbose must be false or Console messages won't be available.")


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

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.

calbach · 2021-03-08T23:58:31Z

e2e/libs/jest-reporter.js

+    // Get test name.
+    const today = new Date();
+    const testName = path.parse(testResult.testFilePath).name;
+    const testLog = `${this.logDir}/${testName}-${today.getFullYear()+'-'+(today.getMonth()+1)+'-'+today.getDate()}.log`;


Why is the date included here? This seems like an odd granularity to choose. If you're trying to use this to get a unique filename, you'll probably need to be more specific (e.g. minute-level). If you want to overwrite previous files, then you may as well just exclude the date entirely.

Right. I want overwrite. Removed time string.

calbach · 2021-03-09T00:04:46Z

e2e/puppeteer-custom-environment.ts

        break;
      default:
        break;
    }
-
+    if (this.failedTest && event.name === 'test_start') {
+      event.test.mode = 'skip';


I don't understand what is happening here, please add comments

jest-circus is used as jest runner. It hooks into test event and state data.
It's fail fast. Because I can't use bail option with a custom logger, I have to find another way to stop other tests from running after first failure. If first failure has happened, all following unexecuted tests will be marked as skip.
Comments also added to file.

calbach · 2021-03-09T00:05:19Z

e2e/libs/logger.js

+  format: format.combine(
+    format.prettyPrint(),
+    format.splat(),
+    format.timestamp({ format: 'YYYY-MM-DD HH:mm:ss' }),


calbach · 2021-03-09T00:06:45Z

e2e/libs/jest-reporter.js

+        options: { flags: 'w' },
+        handleExceptions: true,
+      });
+    fileLogger.clear().add(transports);


Can you explain the decision to use a single logger and then replace the output file - instead of creating a separate logger for each test case? Could you not just create a new one right here rather than mutating shared global state?

Actually, I'm creating a new instance of winston logger here. Creating a separate log file for each test case. I didn't want to include fileLogger here is because it might be reusable for other purpose in future.

On second thought: I think I know what you meant. It's a good idea.
Moving fileLogger code to here. creating a new log file for every test.

Hmm, I realized I asked for this, but am I understanding correctly that now the network log / console logs will not be in the individual test case log files? If so - would probably just revert to the previous approach if you can't use individual loggers there.

It will be very useful to have a clear separation of network logs across test cases - right now it's hard to tell since you have to scan the logs to know how far back you can look for the problematic test case.

Test network and console logs will be saved in individual test log file. they're not lost. It should be easier to read the test log when a failure has happened.

True, I do seem them in the Circle run. I'm confused as to how they are getting there though, since this initial jest setup seems to reference the global logger: https://github.com/all-of-us/workbench/pull/4660/files#diff-9771f32e200b100d3bf9acedfc38dae6209ad815c5e214a31719188ddd392f1dR128

I see. That logger object is a separate winston logger that only logs to console. It doesn't have a file transport.
However, console logs are automatically saved by jest and later they can be retrieved in onTestResult function when verbose: false.

calbach · 2021-03-09T00:08:34Z

e2e/jest.test-setup.ts

    return jsHandle.executionContext().evaluate(obj => {
+      if (obj instanceof Error)


Please use brackets, also please add a comment - I don't follow this

aweng98 · 2021-03-09T18:18:24Z

e2e/jest.test-setup.ts

    } 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) => {


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

calbach

One follow-up comment inline: please address before merging.

Also, from looking at the CircleCI page, I'm noticing it's actually pretty hard to know which logfile I should open to get more details, since I have to dig into the logs to figure out the test suite name, and map that to which one failed. Have you considered ways of addressing this? For example - if a test suite fails, maybe move these into separate pass/fail directories, or rename them to "FAILED", or possibly just remove the logfiles for passing suites?

Also - thoughts on splitting by individual test case, rather than test suite? I think test suite is probably OK for now, but something we may want to consider if this becomes problematic for debugging

calbach · 2021-03-09T21:40:42Z

e2e/libs/jest-reporter.js

+        options: { flags: 'w' },
+        handleExceptions: true,
+      });
+    fileLogger.clear().add(transports);


Hmm, I realized I asked for this, but am I understanding correctly that now the network log / console logs will not be in the individual test case log files? If so - would probably just revert to the previous approach if you can't use individual loggers there.

It will be very useful to have a clear separation of network logs across test cases - right now it's hard to tell since you have to scan the logs to know how far back you can look for the problematic test case.

aweng98 · 2021-03-09T22:20:39Z

e2e/libs/jest-reporter.js

+    let testLogName;
+    testResult.testResults.forEach((result) => {
+      const status = result.status;
+      if (status === 'failed') {
+        testLogName = `${this.logDir}/${testName}-FAILED.log`;
+      } else {
+        testLogName = `${this.logDir}/${testName}.log`;
+      }
+    });


More verbose code but it does the job to find failed test log a little easier. FAILED string is added to log file name.

aweng98 changed the title ~~Aw/e2e jest reporter~~ [no ticket][risk=no] Puppeteer test log improvement Mar 8, 2021

aweng98 commented Mar 8, 2021

View reviewed changes

aweng98 requested a review from calbach March 8, 2021 18:15

calbach reviewed Mar 9, 2021

View reviewed changes

aweng98 marked this pull request as ready for review March 9, 2021 15:09

aweng98 force-pushed the aw/e2e-jest-reporter branch from d2d8d0b to 12f9dc0 Compare March 9, 2021 18:16

aweng98 commented Mar 9, 2021

View reviewed changes

calbach approved these changes Mar 9, 2021

View reviewed changes

aweng98 commented Mar 9, 2021

View reviewed changes

aweng98 added 17 commits March 9, 2021 19:00

wip

ac4e962

wip

5411cd6

save jest log to file

ba77ae7

winston logger

99f9d03

write individual test log

75fee20

save

4d05fa3

remove jest bail

bf0ec33

remove @jest npm packages

aa8af81

jest bail alternative

afd2831

ci retest

66a6ea5

redundant --no-color option

bed19da

consistent test report title

1b951df

PR feedback

24d0b47

create winston file logger in jest-reporter.js

f7c4614

revert last commit

af3e4a0

failed test log file name is FAILED

3b21566

remove bail alternative bc it's not working for parallism

d5ae159

aweng98 force-pushed the aw/e2e-jest-reporter branch from 7a255a3 to d5ae159 Compare March 10, 2021 00:00

aweng98 merged commit ac0cd0a into master Mar 10, 2021

aweng98 deleted the aw/e2e-jest-reporter branch March 10, 2021 00:27

jmthibault79 mentioned this pull request Jul 26, 2021

[risk=no][no ticket] Await an async call #5302

Merged

8 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

aweng98 commented Mar 7, 2021 •

edited

Loading

aweng98 Mar 8, 2021

aweng98 Mar 8, 2021

aweng98 Mar 8, 2021 •

edited

Loading

aweng98 Mar 8, 2021

aweng98 Mar 8, 2021

calbach left a comment

calbach Mar 8, 2021

aweng98 Mar 9, 2021

calbach Mar 8, 2021

aweng98 Mar 9, 2021

calbach Mar 8, 2021

aweng98 Mar 9, 2021

calbach Mar 8, 2021

aweng98 Mar 9, 2021

calbach Mar 8, 2021

aweng98 Mar 9, 2021

calbach Mar 9, 2021

aweng98 Mar 9, 2021

calbach Mar 9, 2021

calbach Mar 9, 2021

aweng98 Mar 9, 2021

aweng98 Mar 9, 2021

calbach Mar 9, 2021

aweng98 Mar 9, 2021

calbach Mar 9, 2021

aweng98 Mar 9, 2021

calbach Mar 9, 2021

aweng98 Mar 9, 2021

aweng98 Mar 9, 2021

calbach left a comment

calbach Mar 9, 2021

aweng98 Mar 9, 2021

		return jsHandle.executionContext().evaluate(obj => {
		if (obj instanceof Error)

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

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

Conversation

aweng98 commented Mar 7, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aweng98 Mar 8, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

calbach left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

calbach left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aweng98 commented Mar 7, 2021 •

edited

Loading

aweng98 Mar 8, 2021 •

edited

Loading