Print tests that were pending when a timeout occurs #1886

vancouverwill · 2018-08-04T10:08:53Z

Fixes #583

First PR for this project so wanted to get some eyes on it before I spent too much time on it and check I am moving in the right direction 😄

Worked on so far

keeping track of which tests are running and updating them when finished
updating test summary to include list of running tests with their files. See example below

✔ fast
  ✖ Exited because no new tests completed within the last 1000ms of inactivity
   3 tests still running
  ◌ /Users/will/development/js/ava/test/fixture/long-running.js:slow
  ◌ /Users/will/development/js/ava/test/fixture/long-running.js:slow two
  ◌ /Users/will/development/js/ava/test/fixture/long-running.js:slow three
  1 test passed

Still to do

run this summary after interrupting AVA i.e. from SIGTERM

Unknowns

What the Tap and Mini reporters are for?
Would you like extra tests in test/reporters/verbose.js, what format should these be in?

novemberborn

Great start @vancouverwill!

What the Tap and Mini reporters are for?

You can ignore the TAP reporter for this.

The mini reporter is very much like the verbose reporter, so much so that I've been intending to merge them. Perhaps for now just focus on the verbose reporter.

Would you like extra tests in test/reporters/verbose.js, what format should these be in?

Yes please! Reporter tests live in test/reporters. We record their output and compare it against a snapshot. You should add this scenario in https://github.com/avajs/ava/blob/master/test/reporters/verbose.js and configure the timeout option in https://github.com/avajs/ava/blob/master/test/helper/report.js. Then run tests using npx tap --no-cov 'test/reporters/*.js'.

Use UPDATE_REPORTER_LOG=1 npx tap --no-cov 'test/reporters/*.js' to update the reporter snapshots.

Let me know if you have any other questions 👍

novemberborn · 2018-08-05T17:08:15Z

lib/reporters/verbose.js

@@ -70,6 +70,8 @@ class VerboseReporter {
 		this.failures = [];
 		this.filesWithMissingAvaImports = new Set();
 		this.knownFailures = [];
+		this.runningTestFiles = {};


Use a Map.

novemberborn · 2018-08-05T17:08:25Z

lib/reporters/verbose.js

+	addTestRunning(evt) {
+		this.runningTestsCount++;
+		if (this.runningTestFiles[evt.testFile] === undefined) {
+			this.runningTestFiles[evt.testFile] = {};


Use a Set.

novemberborn · 2018-08-05T17:08:45Z

lib/reporters/verbose.js

+	/**
+	 * Generates the summary string of tests that are still running
+	 * @returns string
+	 */


To be honest we don't really bother with these comments 😄

Could you remove this comment?

novemberborn · 2018-08-05T17:11:17Z

lib/reporters/verbose.js

 				break;
 			case 'timeout':
-				this.lineWriter.writeLine(colors.error(`${figures.cross} Exited because no new tests completed within the last ${evt.period}ms of inactivity`));
+				this.lineWriter.writeLine(colors.error(`${figures.cross} Exited because no new tests completed within the last ${evt.period}ms of inactivity\n${this.runningTestSummary()}`));


timeout applies to the set of test files that are currently running. However unless --fail-fast is set, AVA will continue to run remaining test files. This means multiple timeouts may occur.

We should include the timed out files when the event is emitted:

ava/api.js

Line 77 in 55e4021

runStatus.emitStateChange({type: 'timeout', period: timeout});

Then if you pass the evt to runningTestSummary() we could print the files appropriate for each particular timeout.

novemberborn · 2018-08-05T17:15:31Z

test/integration/assorted.js

+		t.notMatch(stdout, /.*long-running.js:fast.*/, 'the fast test should not still be shown as running');
+		t.match(stdout, /.*long-running.js:slow.*/);
+		t.match(stdout, /.*long-running.js:slow two.*/);
+		t.match(stdout, /.*long-running.js:slow three.*/);


This timeout test ought not to be here. I think I left it in on purpose since it was reasonably small, but obviously that's no longer the case 😄 Let's remove these additions and write a reporter test instead.

Could you remove the new assertions in this test, and undo the changes in long-running.js?

vancouverwill · 2018-08-14T21:56:20Z

hi @novemberborn thanks for the pointers so far 😄

I used the set() and map() like you said and created new tests in test/reporters/verbose.js and these are in the fixtures folder within test/fixture/report/timeoutinmultifiles/... and test/fixture/report/timeoutinsinglefile/... .

Within test/helper/report.js I have updated the timeout, this caused me some issues as I was passing in straight ms i.e. 1000 but this was getting converted to a string 1s because of the library ms we use and I didn't notice that straight away but even when I pass in the correct format for that library
timeout: type.substring(0,7) === 'timeout' ? "1000ms" : undefined, it gets passed through to the api but the api timeout function never completes.

Within api.js I have logged out what the given timeout argument is and this is the same in my new tests as what is passed in the original integration/assorted.js tests but for whatever reason the timeout never gets triggered and all the tests end up passing.

Apologies because I have put a lot of in Api.js and the Verbose reporter trying to determine why the timeout never finishes but so far have not been able to track it down. So I wondered if you had any pointers as to why the timeout is not getting triggered? 😕

Many thanks, Will 😄

novemberborn

I wondered if you had any pointers as to why the timeout is not getting triggered? 😕

OK I figured it out. Took me a little while, too! In short… it's because the tests mock the Date object. Timeout detection relies on the date actually changing, which it doesn't…

We mock the Date to ensure the logs are the same wherever and whenever the tests are run. I'll push a commit which restores it for the timeout tests.

I've left some other comments, too. Please run npx xo --fix to fix linting issues.

In https://github.com/avajs/ava/blob/846920a40c10427c187bdffa51737e907733efbc/api.js#L72:L77 you should record the workers that are being exited because of this timeout, and then pass their file paths in the timeout event object.

Then in the reporter, you should pass those file paths to runningTestSummary() and only print the pending tests from the workers that were exited.

This is needed since AVA will continue running more test files, which themselves could time out, and we don't want the same tests to be printed multiple times.

Thanks for your hard work on this @vancouverwill!

novemberborn · 2018-08-19T16:22:52Z

test/helper/report.js

@@ -139,5 +139,7 @@ exports.regular = reporter => run('regular', reporter);
 exports.failFast = reporter => run('failFast', reporter);
 exports.failFast2 = reporter => run('failFast2', reporter);
 exports.only = reporter => run('only', reporter);
+exports.timeoutInSingleFile = reporter => run('timeoutinsinglefile', reporter);
+exports.timeoutInMultiFiles = reporter => run('timeoutinmultifiles', reporter);


Let's camelCase the type values, like with failFast.

Let's use timeoutInMultipleFiles rather than "multi files".

novemberborn · 2018-08-19T16:23:46Z

test/helper/report.js

@@ -97,7 +97,7 @@ const run = (type, reporter) => {
 		babelConfig: {testOptions: {}},
 		resolveTestsFrom: projectDir,
 		projectDir,
-		timeout: undefined,
+		timeout: type.substring(0,7) === 'timeout' ? "1000ms" : undefined,


Use type.startsWith('timeout').

novemberborn · 2018-08-19T16:56:30Z

lib/reporters/verbose.js

+	/**
+	 * Generates the summary string of tests that are still running
+	 * @returns string
+	 */


Could you remove this comment?

novemberborn · 2018-08-19T16:57:43Z

test/integration/assorted.js

+		t.notMatch(stdout, /.*long-running.js:fast.*/, 'the fast test should not still be shown as running');
+		t.match(stdout, /.*long-running.js:slow.*/);
+		t.match(stdout, /.*long-running.js:slow two.*/);
+		t.match(stdout, /.*long-running.js:slow three.*/);


Could you remove the new assertions in this test, and undo the changes in long-running.js?

novemberborn · 2018-08-19T17:06:54Z

lib/reporters/verbose.js

+		let smy = ` ${this.runningTestsCount} tests still running`;
+		this.runningTestFiles.forEach((tests, file) => {
+			for(let test of this.runningTestFiles.get(file)) {
+				smy += `\n${figures.circleDotted} ${file}:${test}`;


Use this.prefixTitle(file, title) instead.

novemberborn · 2018-08-19T17:07:00Z

lib/reporters/verbose.js

+		}
+		let smy = ` ${this.runningTestsCount} tests still running`;
+		this.runningTestFiles.forEach((tests, file) => {
+			for(let test of this.runningTestFiles.get(file)) {


Change test to title.

novemberborn · 2018-08-19T17:07:26Z

lib/reporters/verbose.js

+		if (this.runningTestsCount === 0) {
+			return 'NO TESTS 🍓';
+		}
+		let smy = ` ${this.runningTestsCount} tests still running`;


You don't need to add the space. However let's put a \n in front and put a colon after running.

novemberborn · 2018-08-19T17:10:48Z

I'll push a commit which restores it for the timeout tests.

@vancouverwill could you allow edits from maintainers on this PR so I can push my fix?

vancouverwill · 2018-08-19T17:34:14Z

Hey @novemberborn thanks for those comments, will look into them. With regard to access it looks like it already is set to that as far as I can see 😄

novemberborn · 2018-08-19T19:21:53Z

With regard to access it looks like it already is set to that as far as I can see 😄

Yes. My "push to the PR branch" script got confused about the slash in the branch name. I've pushed my fix now, let me know if you have any further questions!

…ting test summary to include list of running tests with their files

… their uses are

…s for each file

vancouverwill · 2018-08-31T22:37:56Z

hey @novemberborn I made the changes you suggested and the different files timeout separately with their own respective error messages.

Wasn't sure what you guys prefer to do for commit messages, whether you like to squash them or keep the major ones around for histories sake, they are in there for now but happy to squash them if you prefer.

Thanks

Will

…ding tests

novemberborn

Wasn't sure what you guys prefer to do for commit messages, whether you like to squash them or keep the major ones around for histories sake, they are in there for now but happy to squash them if you prefer.

This is a pretty focused PR, so we'll do a squash and merge.

I've left some inline comments but I figured we've been doing a back and forth dance for a while now, and I feel a bit bad about that. I'm going to push some changes that address my comments. Let me know what you think and then we can land this.

lib/reporters/verbose.js

novemberborn · 2018-09-09T15:18:17Z

lib/reporters/verbose.js

+		for (const timedOutFile of evt.timedOutWorkerFiles) {
+			const currentFile = this.runningTestFiles.get(timedOutFile);
+			if (currentFile) {
+				smy += `\n${this.runningTestsCount} tests still running in ${timedOutFile}:`;


We can actually take currentFile.size. runningTestsCount is a global count.

vancouverwill · 2018-09-09T21:40:22Z

ahh that's awesome. thanks for your patience with the back and forth, I know there has been a fair bit of chat but it is the first time me working on the project so there is bound to more questions than there would normally be.

Anyway cheers for the help, I'm definitely happy to get it out. Our team use ava all the time and being able to see which files have timed out will be really useful

And good point about ". runningTestsCount is a global count.", I had assumed originally that timeout was a global state and still had that way of thinking I guess.

novemberborn · 2018-09-10T08:30:14Z

@vancouverwill awesome.

Was about to merge this and then I realized the PR said this would work on interrupts too, and I don't think we're testing that yet. Will have a look to see what state this PR is actually in, and then merge it with the correct commit message 😉

vancouverwill · 2018-09-10T12:49:22Z

ahh true, I was so focused on timeouts but that was part of the orginal plan. Should be able to reuse a lot of the same logic for timeouts tho so I can add the code on here or better yet get this out and we can do another pr for the interrupts?

…

On Mon, Sep 10, 2018 at 9:31 AM Mark Wubben ***@***.***> wrote: @vancouverwill <https://github.com/vancouverwill> awesome. Was about to merge this and then I realized the PR said this would work on interrupts too, and I don't think we're testing that yet. Will have a look to see what state this PR is actually in, and then merge it with the correct commit message 😉 — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#1886 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA4ZIyHIM08-DYvCJcutYtajeds0-zVKks5uZiNGgaJpZM4Vu75E> .

novemberborn · 2018-09-11T08:18:11Z

better yet get this out and we can do another
pr for the interrupts?

Yup that's the plan. Just need to have another look at it.

vancouverwill force-pushed the wm/keepTrackOfTestsNotPassing branch from 8672685 to 4d825c7 Compare August 4, 2018 10:15

novemberborn requested changes Aug 5, 2018

View reviewed changes

vancouverwill force-pushed the wm/keepTrackOfTestsNotPassing branch 2 times, most recently from 1fd483e to cf002dc Compare August 14, 2018 21:47

novemberborn requested changes Aug 19, 2018

View reviewed changes

sindresorhus changed the title ~~Fixes issue #583 - Print pending tests when interrupting AVA, or after a timeout~~ Print pending tests when interrupting AVA or after a timeout Aug 20, 2018

vancouverwill force-pushed the wm/keepTrackOfTestsNotPassing branch 5 times, most recently from 4030f32 to 85bfc10 Compare August 31, 2018 22:24

vancouverwill and others added 6 commits August 31, 2018 23:31

logging which tests are running and updating them when finished; upda…

f9b8536

…ting test summary to include list of running tests with their files

use map and set for files and tess respectively as more explicit what…

9e608d2

… their uses are

timeout tests

1e8148a

tests for timeouts in multiple files

59a804c

Restore timers before running verbose timeout tests

1f64ecf

get tests to work with different timeouts and different error message…

45a97c2

…s for each file

vancouverwill force-pushed the wm/keepTrackOfTestsNotPassing branch from 85bfc10 to 45a97c2 Compare August 31, 2018 22:37

novemberborn added 6 commits September 9, 2018 15:58

Merge branch 'master' into pr/1886

1d7333e

Fix syntax error

a4a6fb7

Fix linting issues

603d076

Use linewriter to write the timeout summary, simplify tracking of pen…

9ff9ef5

…ding tests

Fix whitespace in fixtures

8d2987f

Revert regular verbose log changes

05c60f1

novemberborn reviewed Sep 9, 2018

View reviewed changes

novemberborn approved these changes Sep 9, 2018

View reviewed changes

novemberborn changed the title ~~Print pending tests when interrupting AVA or after a timeout~~ Print tests that were pending when a timeout occurs Sep 15, 2018

novemberborn merged commit 6d12abf into avajs:master Sep 15, 2018

novemberborn mentioned this pull request Sep 15, 2018

Print pending tests when interrupting AVA, or after a timeout #583

Closed

Print tests that were pending when a timeout occurs #1886

Print tests that were pending when a timeout occurs #1886

Uh oh!

Conversation

vancouverwill commented Aug 4, 2018 • edited by sindresorhus Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Worked on so far

Still to do

Unknowns

Uh oh!

novemberborn left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vancouverwill commented Aug 14, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

novemberborn left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

novemberborn commented Aug 19, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

vancouverwill commented Aug 19, 2018

Uh oh!

novemberborn commented Aug 19, 2018

Uh oh!

vancouverwill commented Aug 31, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

novemberborn left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vancouverwill commented Sep 9, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

novemberborn commented Sep 10, 2018

Uh oh!

vancouverwill commented Sep 10, 2018 via email

Uh oh!

novemberborn commented Sep 11, 2018

Uh oh!

Uh oh!

vancouverwill commented Aug 4, 2018 •

edited by sindresorhus

Loading

vancouverwill commented Aug 14, 2018 •

edited

Loading

novemberborn commented Aug 19, 2018 •

edited

Loading

vancouverwill commented Aug 31, 2018 •

edited

Loading

vancouverwill commented Sep 9, 2018 •

edited

Loading