When global timeouts occur, show unfinished tests, not pending ones

[novemberborn]

When a global timeout occurs, we currently print all pending tests, like here:

ava/lib/reporters/verbose.js

Line 163 in b6a46bd

this.writePendingTests(evt);

The problem is that these tests have not necessarily started. For instance, if they're declared as test.serial(), or if they're non-asynchronous test()s.

We should only print those tests and hooks that have started.

It may be the case that internally we're not yet tracking this, and there might be some false negatives if the timeout triggers before the starting can be communicated to the main process.

This is based on this discussion: #2384 (comment)

[sramam]

It'd be really useful to have the duration a test was running for along with this change.

[mesqueeb]

I've recently starting to see this a lot of the time I run all my tests:

✖ Timed out while running tests

I only have async tests, I guess some are taking longer than AVA allows?

The thing is, even though all my tests are async, my custom mocks only use a timeout of 1 ms: setTimout(() => {}, 1)

Should I open a new issue for this? When searching for related issues it brought me here.

[novemberborn]

I've recently starting to see this a lot of the time I run all my tests:

✖ Timed out while running tests

I only have async tests, I guess some are taking longer than AVA allows?

@mesqueeb note that with AVA 3, we've set a default inactivity timeout of 10 seconds. Before there was no default.

It may be that you have too many concurrent tests and they're slowing each other down. Try using more test files, or using test.serial(). You can also try increasing the timeout (timeout: '30s' in the configuration).

[sramam]

Perhaps this deserves a separate issue, but will log it here and move if that seems more appropriate.

This is the console log I see:

> cross-env NODE_ENV=test nyc -r lcov -r text-summary -r json-summary ava --verbose -T 30000

  ✔ declschema › declaratif schema test (6.6s)
  ✔ declschema › declaratif schema test - generic (3.9s)
  ✔ declschema › declaratif schema test - generic-multiple (2.3s)
  ✔ declschema › declaratif schema test - interface-extends (1.1s)
  ✔ defs › remove unused definition B
  ✔ defs › no unused definitions
  ✔ defs › nested no unused definitions
  ✔ defs › no definitions
  ✔ defs › empty definitions
  ✔ defs › many unused definitions
  ✔ defs › all unused definitions
  ✔ defs › complex component config
  ✔ defs › Reference to unknown definition should not throw error
  ✔ config › expose-all-topref-true (12.4s)
  ✔ config › expose-all-topref-false (6.2s)
  ✔ config › js-doc-tags-basic (2.5s)

  ✖ Timed out while running tests


  16 tests passed

What's happening is that one test file has a before() implementation that needs to make network access that exceeds the 30s global timeout setup (actually it only happens intermittently on the CI system - a bit of a detour to reason about)

Seem it would probably be a good idea to track the before*/after* tasks in flight (in addition to the tests) and report them on timeout.

[novemberborn]

@sramam to clarify, what are you expecting to see here?

[sramam]

Just some indication that it's not the test itself, but which setup/teardown that timed-out.
On larger suits, with multiple authors, I can see how it'll be a nightmare to figure the culprit.

The output as presented above basically says there was a timeout, but everything passed.
Especially when it's intermittent, I'd like to know if it was because of changes just introduced
or because of some other property- CI system, network access, network throughput etc.
But to diagnose these, I need to know what timed-out as a first step. Else, I could be playing whack-a-mole all day long and not develop a sense for the root cause of the problem.

[novemberborn]

@sramam thanks. That makes sense. I've updated the issue summary to read:

We should only print those tests and hooks that have started.

[novemberborn]

Both due to the age of this issue, and the state of our reporters, I've decided to roll this into #2501.