Test suite times out but all tests have "passed"

[ships]

Hi friends, I have been using AVA successfully to run unit tests. I added a test to the suite that is measuring performance, so I expect it to take a little longer. The full test code is at the end for completeness, but the behavior I'm seeing is contradictory (it seems?) regardless of what is in the test.

What happens when I run my updated test suite is the fast unit tests all complete with passed check mark sign in AVA stdout, then a brief pause as the perf test is run, then that test is marked as passed as well. Then there is a pause of ten seconds, and AVA's timeout kicks in: ✘ Timed out while running tests . Then, even weirder, the process hangs; historically, timeouts then have resulted in AVA exiting nonzero.

When I remove my perf test, the suite passes as usual.

When I include t.timeout(20000) in the perf test, I expect the same error to occur after 20 seconds rather than 10, but... it never does! The process hangs with all of my tests showing passed.

It seems to me that AVA is hung up on some background process or open handle or something, but how can I go about diagnosing this? It's quite possible that my perf test shows that something is leaked but i am unable to see what, and anyway it's surprising to me because the test supposedly has exited (otherwise it wouldn't show as Passed) but the t.timeout inside that test's execution block still makes the suite hang.

Here's the perf test. Note that in terms of setup and teardown, it is identical to another test except with addition of the for loop (the unit test performs 1 query only). So if resources are leaked, AVA is managing to clean them up when the scope is small.

test.serial('query performance in simple scenario', async (t) => {
  t.timeout(20000)
  const backend = fixtures.CreateDatastore()

  const processor = new SparqlAdapter(backend)

  const start = new Date()

  for (let i = 0; i < 1000; i++) {
    await processor.docmapWithIri(
      'https://data-hub-api.elifesciences.org/enhanced-preprints/docmaps/v1/get-by-doi?preprint_doi=10.1101%2F2022.11.08.515698',
    )()
  }

  const end = new Date()
  t.true(end.getTime() - start.getTime() < 10000)
})

[novemberborn]

The timeout can occur even after all tests have completed, since AVA does wait for the worker thread to exit. However when it does, it should terminate any remaining worker threads. It's unclear to me from the Node.js documentation whether this itself can fail.

t.timeout() disables AVA's inactivity timer for the duration, and it only restarts if there's more activity afterwards. So you end up in a situation where there is no activity and the process is not exiting.

It's hard to say more without instrumenting the installed copy of AVA, or debugging / instrumenting the worker thread to see why it's not exiting.

[ships]

@novemberborn thanks for the note. I would be interested to try instrumenting the AVA, is there a reference sheet you could recommend for pointers? Generally speaking any insight I can get into the behavior of this system under test is valuable to me!

Cheers from a scorpio

[novemberborn]

These lines are probably of interest:

• ava/lib/api.js

  Line 120 in 306e37c

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

• ava/lib/api.js

  Line 300 in 306e37c

  pendingWorkers.delete(worker);

• ava/lib/api.js

  Line 292 in 306e37c

  timeoutTrigger.ignoreFor(data.period);

• ava/lib/fork.js

  Line 167 in 306e37c

  forcedExit = true;

[novemberborn]

There's some progress here #3259.