"✖ Timed out while running tests" are not reported as failing tests

[TimDaub]

I'm running my test suite using ava --serial --verbose.
In the past, there have now been several cases where random tests start failing. This is reported by ava as follows:

src › controllers › calendar_test › if endpoint redirects
test/src/controllers/calendar_test.js:161

   160:  code                                                   
   161:  other code                                                    
   162:  some code

  Rejected promise returned by test. Reason:

  SqliteError {}

  › test/src/controllers/calendar_test.js:161:5

So then I wonder what's happening. Often, I then discover way up in the logs that many tests have started failing because they timed out.

✖ Timed out while running tests

  7 tests were pending in test/src/api/v1_test.js

  ◌ src › api › v1_test › a
  ◌ src › api › v1_test › b
  ◌ src › api › v1_test › c
  ◌ src › api › v1_test › d
  ◌ src › api › v1_test › e
  ◌ src › api › v1_test › f
  ◌ src › api › v1_test › g

However, these tests are not shown as "failing" in the end. Instead, the "XY tests passed" output is just decreased by the number of tests that timed out. In many cases, this isn't appropriately notifying me. Meaning, I'll just assume all tests have passed and continue my work.

For tests that time out though, what I'm expecting is that there's - as with failing tests - a big red warning and stack trace to make me aware.

Is there any option that can be enabled such that ava treats timed-out tests as failed tests?

[novemberborn]

I'm struggling to remember quite what everything looks like — I appreciate you can't share your full test run but it makes it tricky to look at it from your perspective and see where the output can be clearer. Do you think you could share a bit more?

I'd expect a summary with the numbers of passing, failing, timed out tests, etc. And a list of failures and timeouts.

I'm pretty sure the output can be improved though, and it's probably worse without --verbose. Thanks for raising this.

[TimDaub]

Hey @novemberborn,

I can send you a full log if you give me a private comms channel e.g. email.

[tymfear]

So recently the similar issue was addressed in TAP reporter - now all specs that haven't been run due to timeout are reported as failed. And when I was working on that I was also wondering why default reporter does not do similarly. So probably AVA should report all tests that are pending when timeout occurs as failed in all reporters (including the JSON reporter created via #2608 )?

[novemberborn]

@tymfear sure but that's because we're trying to shoehorn AVA's behavior into the TAP spec.

For our own reporters, as long as the exit code is non-zero and it's clear from the output what happened we're good.

[TimDaub]

Hey @novemberborn,

I created a quick repo to show you what I mean: https://github.com/TimDaub/ava-test-timed-out
Here's a full log of a test run (--verbose):

name@machine  ~/Projects/ava-test-timed-out   master  npm run test

> [email protected] test /Users/name/Projects/ava-test-timed-out
> ava --verbose


  ✔ another test that is simply passing

  ✖ Timed out while running tests

  1 tests were pending in test/index_test.js

  ◌ a test that times out

  ─

  1 test passed
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] test: `ava --verbose`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the [email protected] test script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/name/.npm/_logs/2021-01-05T10_51_03_888Z-debug.log
 ✘ name@machine  ~/Projects/ava-test-timed-out   master 

I mean it's fairly obvious with this log that something must be wrong as ava reports an error code 1. However, imagine you have many more tests...

[novemberborn]

What if we add 1 test remained pending after a timeout at the end there?

[TimDaub]

sounds good to me!

[TimDaub]

@novemberborn: If you'd provide me some guidance, I'd probably be able to help make the change myself.

[novemberborn]

@TimDaub you'll want to have a look at this function:

ava/lib/reporters/default.js

Line 653 in 32c5425

endRun() {// eslint-disable-line complexity

Perhaps store the timed out and interrupted tests:

• ava/lib/reporters/default.js

  Line 279 in 32c5425

  this.writePendingTests(event);

• ava/lib/reporters/default.js

  Line 286 in 32c5425

  this.writePendingTests(event);

Have a look here to figure out the object structure:

ava/lib/reporters/default.js

Lines 465 to 473 in 32c5425

	writePendingTests(evt) {
	for (const [file, testsInFile] of evt.pendingTests) {
	if (testsInFile.size === 0) {
	continue;
	}
	this.lineWriter.writeLine(`${testsInFile.size} tests were pending in ${this.relativeFile(file)}\n`);
	for (const title of testsInFile) {
	this.lineWriter.writeLine(`${figures.circleDotted} ${this.prefixTitle(file, title)}`);

(And yea this code has accumulated a lot of cruft over the years.)

[TimDaub]

Thanks, @novemberborn. I'll try to give it a look this week and keep you posted.

[stavalfi]

If that's help, this PR fixes it: #2647

[TimDaub]

@stavalfi thanks for pointing to your PR, but I don't think it fixes the problem in this issue. I'm coming to that conclusion as you're not editing the code that handles a type: "timeout" event.

I'm happy of course if I'm wrong, so feel free to run your branch on: https://github.com/TimDaub/ava-test-timed-out

[jakobrosenberg]

Is it possible to force this message × Timed out while running tests without --verbose?

If I insert

await new Promise(resolve => setTimeout(resolve, 20000))

into a test I get 99 tests passed instead of 100 tests passed. If I don't know the exact number of tests being run (I don't), I would assume all tests are passing (I did).

[novemberborn]

Is it possible to force this message × Timed out while running tests without --verbose?

Yes that ought to work.