"Timed out while running tests"

[sculpt0r]

I've just started receiving more and more timed out. TBH It is rare to run proper tests... My config:

process.env.TS_NODE_PROJECT = './tsconfig.test.json';

module.exports = {
	failWithoutAssertions: false,
	extensions: [ 'js', 'ts' ],
	files: [ './src/**/tests/**/*.ts', '!./src/**/tests/_utils/**/*.ts' ],
	require: [ 'ts-node/register', 'source-map-support/register' ]
};

I'm not sure what else I could add here - because there is no errors in the console, only

Increasing the timeout in config or in the single test does not help at all...

It looks like the async tests cause this trouble: test( '', async t => {} ): Running a single test without async works fine - and the results seem to appear exactly at the moment when the Timed out appears in async test 🤔

AVA: 4.2.0
Node: Tried various: 16.11.0. 16.15.0, 17.9.0, 18.2.0
OS: MacOS 12.2.1

Originally posted by @sculpt0r in #2494 (comment)

[sculpt0r]

I've managed to stabilize tests by adding:

workerThreads: false,
timeout: '80s'

But I would rather say that it looks like a workaround rather than a solution. Does the test cases total amount, test files amount or test cases per file somehow impact the performance? And that might influence the amount of the timeout?

One additional thing: I'm managing the nodeJS versions via nvm.

[novemberborn]

Timeouts occur when there is no single test passing for the timeout duration (defaulting to 10 seconds if I'm not mistaken). Essentially if your test suite isn't making progress, then AVA gives up.

async or not depends on what your test is actually doing. It sounds like it's synchronous (otherwise why would it pass without async?). Technically then the tests still run synchronously, it's just the outcome that is observed asynchronously.

I wonder if this is related to ts-node, #3031 suggests a timeout problem with ts-node. That's a little outside of AVA though.

Have you tried with precompiled files using @ava/typescript?

[sculpt0r]

Not yet, but I will give it a try - thanks. I will provide te results here or any other observations - thank you for the response :)

[sculpt0r]

Added, the @ava/typescript, and in the config I put an extra:

compile: 'tsc'

Still need to have timeout: '80s' but I removed the workerThreads: false. This time instead of Timed out I receive:

Also, I'm pasting the text for sake of copy/paste

#
# Fatal error in , line 0
# Check failed: result.second.
#
#
#
#FailureMessage Object: 0x5997dbd70
 1: 0x1050ebef2 node::NodePlatform::GetStackTracePrinter()::$_3::__invoke() [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 2: 0x1060c1f13 V8_Fatal(char const*, ...) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 3: 0x1054da8fe v8::internal::GlobalBackingStoreRegistry::Register(std::__1::shared_ptr<v8::internal::BackingStore>) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 4: 0x1052110e6 v8::ArrayBuffer::GetBackingStore() [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 5: 0x105056fcb node::Buffer::Data(v8::Local<v8::Value>) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 6: 0x1050859db node::fs::Read(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 7: 0x1052673b9 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 8: 0x105266e86 v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
 9: 0x1052665ff v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
10: 0x105ad9af9 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit [/Users/CKS/.nvm/versions/node/v16.15.0/bin/node]
11: 0x1558c56a3 
12: 0x1558c5859 
13: 0x1558c8ecd

Funny thing, the CI seems to be more stable (or there is no issue at all) 🤔

I didn't mentioned, but I have mac with M1, however the problem also appears on linux 🤔

[novemberborn]

Would be interesting to try with compile: false and precompile. That way there is no compilation involved at all when AVA runs.

Your crash is something in Node.js itself unfortunately.

[sculpt0r]

Could you guide me a little bit on how to properly set up the avajs/typescript for the project? I already found a similar question But couldn't figure out anything. So far I realized that I should drop the ts-node/register from ava config.require.Then after many ts config tries, I finished with: error TS7016: Could not find a declaration file for module probably for all of the files. The definitions look generated and the declarationDir now points to ./dist/types - but this won't help. 🙇

[novemberborn]

@sculpt0r this may be worth a separate discussion. I'd be eager to see where you're getting stuck so we can improve the documentation.

[sindresorhus]

I'm seeing this issue too: sindresorhus/is#167

"workerThreads": false did not help.

[novemberborn]

@sindresorhus the issue @sculpt0r is describing below could be related to globbing timing out. I've tried with your PR and that's not the case. I'm inclined to blame ts-node. I don't think it's worker thread related.

[sculpt0r]

Another fact:
I've managed to established the Timed out behavior in a particular situation. The test file is in the directory(Letter cases and the length of the path match with the original one):

/Users/XXX/XXXzzzzz/yyy-qqqqqqqqq/src/ccc-bbbbbb/tests/index.ts

and the project root directory is:

/Users/XXX/XXXzzzzz/yyy-qqqqqqqqq

Via VSCode plugin the command is run in the terminal:

cd /Users/XXX/XXXzzzzz/yyy-qqqqqqqqq && npm test /XXX/XXXzzzzz/yyy-qqqqqqqqq/src/ccc-bbbbbb/tests/index.ts

which leads to run:

ava --verbose "/Users/XXX/XXXzzzzz/yyy-qqqqqqqqq/src/ccc-bbbbbb/tests/index.ts"

The file contains:

import test from 'ava';

test( 'pkg exports public api', async t => {
	t.pass();
} );

Result:

However, if I run the same high-level command, but without index.ts, so

cd /Users/XXX/XXXzzzzz/yyy-qqqqqqqqq && npm test /XXX/XXXzzzzz/yyy-qqqqqqqqq/src/ccc-bbbbbb/tests/

which leads to run:

ava --verbose "/Users/XXX/XXXzzzzz/yyy-qqqqqqqqq/src/ccc-bbbbbb/tests/"

I received the time out:

Maybe sth in selecting files to tests leads to timeout?

Sorry for the weird path obfuscating - but the project is private and I'm not allowed to publish any information about it.

[sculpt0r]

☝️ The same happens whether I set the config files property to point at a certain file vs filter like:

files: [ './src/yyy-qqqqqqqqq/tests/**/*.ts' ],

but this one is working:

files: [ './src/yyy-qqqqqqqqq/tests/**/index.ts' ],

[sculpt0r]

For my project - it started when we upgrade to version: 4. I verified the first commits after the upgrade - and they started to throw the timed out. Also, I've tried with the alpha and the newest 4.3.0Still - there is no issue at CI (Circle CI with image: cimg/node:16.11.0) 🤔

[novemberborn]

Interesting!

The timeout is started before we search for the test files. I think the globbing could do with its own timeout and error message.

@sculpt0r could you install npm install -D avajs/ava#debug-globs? Then DEBUG=ava:glob npx ava. It should output something like this:

  ava:glob Find tests +0ms
  ava:glob Found 1 test files, now filtering +10ms
  ava:glob Selected 1 test files +0ms

Let's see if the timeout occurs here.

[sculpt0r]

Just run the "full tests run" with the flag --concurrency 1 and it looks like everything works fine 🤔 I mean tests are still running but I see that there is more and more test cases that passed.

[sculpt0r]

The same for the run with the 'directory' filter: tests passed & no timed outs.

[sculpt0r]

It's selecting the right number of test files for all runs?

Looks like it does - all files are selected 👍

[sculpt0r]

As for the test run with directory filter: the timed out starts to appear when there are 5 test files. If I decrease the amount to 4 files - the tests run properly 🤔 <- With my standard config - so without concurrency or serial flags.

[sculpt0r]

And today it hits also the CI 🤔 This time --concurrency 1 neither --serial didn't help.

[sculpt0r]

@novemberborn - I was able to receive the results you were asking for before. With just timeout: 90s I've got the test run which didn't find all files. I know it because the code coverage is very poor and the CI failed. However - there are no other warnings or messages 🤔

Please don't be mad that I'm posting so many times in this discussion - but the project is important and I want to provide as many details as I'm able to. Hopefully, they can help to find a bug.

Is there a way to tell AVA to output much more details? I mean besides --verbose?

[sculpt0r]

Thanks for the explanation - I will try again :)

[novemberborn]

One thing I just noticed with sindresorhus/is, the AVA process is using loads of CPU. I put in a setInterval() to do some logging right before we load the test file and that didn't do anything. I think that project uses a different hook to load ts-node but the behavior is likely the same as for your project.

[sculpt0r]

Well 😅 I just look into the activity monitor while I run a full test run and...

Just when the memory reaches the 3,93 GB - the timeout comes in 🤔

EDIT:
but that was with turned off workedThreads ;( With default settings:

and the timeout out appear at around ~1,21 GB mem spike 🤔

[novemberborn]

Yes, I'm seeing the same with sindresorhus/is, which only has one test file.

[sculpt0r]

And one more observation - the time out also appears whether some test files have errors - like importing a module that is not exported from another file 🤔

[sculpt0r]

👋 I have finally managed to precompile the test - thank you for the support in avajs/typescript#43. This required a lot of 'fun' and I need to change the way how some tests are written, but... The prebuilded tests are many times faster than before. Also - there are no timeouts!

So I adjust the compile with tsc configuration and ran tests with compile: false in the AVA config. I'm marking this solution as an answer in the discussion. Maybe not ideal for me - but it solves the issue.

But if you are still interested in some debugging why the timeouts come out - I'll be happy to help with my 'problematic' project ;p For the next week I won't respond anything - but after that, I'll be back :) Thank you for your efforts with this issue.

[sindresorhus]

I managed to solve the problem, at least for me. The solution was annoyingly simple. Just add "transpileOnly": true to your ts-node config: sindresorhus/is@2e720ce#diff-b55cdbef4907b7045f32cc5360d48d262cca5f94062e353089f189f4460039e0R10

[sindresorhus]

should we add that to https://github.com/avajs/ava/blob/main/docs/recipes/typescript.md#using-ts-node?

Yes

What is the behavior when that's not set to true?

The old behavior. It times out. And if I increase the timeout to 5 minutes, it eventually crashes for overuse of memory.

[novemberborn]

What is the behavior when that's not set to true?
The old behavior. It times out. And if I increase the timeout to 5 minutes, it eventually crashes for overuse of memory.

I mean, what is it trying to do? You'd think transpiling is the default behavior!

[sculpt0r]

@novemberborn - Actually I marked as a valid answer your original first answer some time ago. Your answer seems to be more valid to me. Tests run fine whether they are precompiled and it is not depend on what stuff was used by te user (tsc / ts-node)

[sculpt0r]

I mean, what is it trying to do? You'd think transpiling is the default behavior!

Looks like it skips type checking?

[Sparticuz]

should we add that to main/docs/recipes/typescript.md#using-ts-node?

Yes

FWIW, it's already there, but more explanation is probably needed, and it should probably be recommended as the default option

It's worth noting that with this configuration, tests will fail if there are TypeScript build errors. If you want to test while ignoring these errors you can use ts-node/register/transpile-only instead of ts-node/register.

[danpalmer]

I've been battling this for a while but finally figured it out (in my instance). Ava intercepts timers in some way and doesn't allow tests to finish until timers (i.e. setTimeout) fire. In my case I had timers set for 5 minutes, but my tests had a 10 second timeout.

I understand why this is something you'd want, particularly for async tests, but I'm not sure the way Ava does it right now is the best. Here are a few suggestions...

Error messages

The tests timing out is a very generic error, as this thread illustrates. I've seen other test frameworks (not in JS/TS) that either raise exceptions by default at the end of a test if there's still ongoing async work like timers, or they log unowned computation in some way. Saying at the end of a test "Warning: there's still a timer running" would have pointed to the solution immediately.

Documentation

It was unclear from documentation that this happens. A mention or callout of some kind on the troubleshooting docs or the timeouts docs would be great in helping to track this down. I lost a few hours to this bug, and probably checked the documentation only a few minutes in. If this exists and I've just not searched for the right thing, apologies, although maybe the text can get a few more searchable keywords in it.

Assertion behaviour

The real benefit from waiting on timers would be for tests to be able to assert. My problem was that I ran a bunch of tests that set timers, and the tests all passed, but then the process timed out. What should have happened was that the individual tests that set timers should have timed out and failed. If this had happened I'd have spotted the issue much earlier, in the end I only figured out the issue after commenting out tests progressively until the tests no longer timed out.

Control over timers

Once I figured out the issue I tried to find a good way to solve it. In an environment that I have more familiarity with (Python, Java, etc), I'd use a fake timer of some kind or a system framework hook to control the time and fast-forward time in the tests so that I could test the timer behaviour. That way the actual time or the time that tests take to run has no impact on the reliability of the test or its ability to assert about the system behaviour. Unfortunately for now I've had to just set the timer to 1s in tests, knowing it's unlikely for any test to take longer than that, and I've had to skip testing the case where the timer fires for now (or would need to write a test that would take >1s to run). Some support from Ava in this would be great.

[novemberborn]

Ava intercepts timers in some way and doesn't allow tests to finish until timers (i.e. setTimeout) fire. In my case I had timers set for 5 minutes, but my tests had a 10 second timeout.

This isn't what's happening. The long-running timer is preventing the test worker from exiting on its own. That's why the error message says "Failed to exit…".

Happy for a PR that changes that message to include some suggestions. I don't know how feasible it is to describe the specific handles that prevent Node.js from exiting. Even "there's a long-running timer" may not be helpful since it could come from a dependency you've loaded.

---

There are fake timer implementations available, lolex comes to mind but https://nodejs.org/docs/latest/api/test.html#class-mocktimers may also do the trick (I haven't had a chance to use it yet).

Also, you can use t.timeout() to set an acceptable timeout just for your test. This is useful if a specific test takes longer than the global timeout value you've set (or the default).