Repository navigation
worker.terminate() never resolves #54
Description
Premise
I am facing a weird issue only on Ubuntu 22.04 when using Vitest. I am opening the issue here because, after a deep investigation, it turned out that it is somehow related to the tinypool worker.
Since the codebase affected by the issue is private, I'll explain the behavior here and try tomorrow to provide a repro repo (I am not sure this is even feasible).
The issue
Several test files prevent Vitest from printing the report (default report), even if the test inside the files passes. The process goes in segmentation fault instead of exiting.
I added several console.logs in vitest and tinypool codebase to understand where things are breaking. It turned out that the Promise at https://github.com/tinylibs/tinypool/blob/main/src/index.ts#L486 was never resolved.
Those are the console log I added:
- before this.pool.runTests -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/node/core.ts#L396
- before pool.run -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/node/pools/threads.ts#L90
- tinypool runTask -> https://github.com/tinylibs/tinypool/blob/main/src/index.ts#L863
- entering vitest/worker.js -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/runtime/worker.ts#L56
- after startViteNode -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/runtime/worker.ts#L57
- timeout 10000 -> https://github.com/tinylibs/tinypool/blob/main/src/index.ts#L471
- after run2 -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/runtime/worker.ts#L57
- after rpcDone -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/runtime/worker.ts#L58
- after inspectorCleanup -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/runtime/worker.ts#L61
- worker terminated -> https://github.com/tinylibs/tinypool/blob/main/src/index.ts#L490
- woker removed -> https://github.com/tinylibs/tinypool/blob/main/src/index.ts#L898
- after pool.run -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/node/pools/threads.ts#L90
- onFinished -> https://github.com/vitest-dev/vitest/blob/ba3d133836513cb08f7ded6db67119cf3e715ac4/packages/vitest/src/node/core.ts#L433
This is the output when the this issue is present:
$ npx vitest run bugged.test.ts
before this.pool.runTests
before pool.run
tinypool runTask
entering vitest/worker.js
after startViteNode
❯ bugged.test.ts (1)
⠹ my test
timeout 10000
after run2
after rpcDone
after inspectorCleanup
✓ bugged.test.ts (1)
Segmentation fault (core dumped)
On the other hand this is the output when there is no segfault
$ npx vitest run passing.test.ts
before this.pool.runTests
before pool.run
tinypool runTask
entering vitest/worker.js
after startViteNode
❯ passing.test.ts (1)
⠸ my test
after run2
after rpcDone
after inspectorCleanup
worker terminated
worker removed
after pool.run
Test Files 1 passed (1)
Tests 1 passed (1)
Start at 16:39:48
Duration 2.27s (transform 588ms, setup 363ms, collect 1.08s, tests 99ms, environment 0ms, prepare 76ms)
onFinished
timeout 10000
Vitest version v0.30.1
Tinypool version 0.40.0
Would you happen to have any ideas why this is happening or what I can do to understand the underlying issue better? Do you think this is a vitest bug?
Activity
Aslemammad commentedon Apr 13, 2023
Hey, Thank you so much!
@AriPerkkio any idea?
AriPerkkio commentedon Apr 14, 2023
Is your codebase using any native node addons, either directly or through dependencies? The segmentation fault crash would indicate that there is a native code running that's trying to access invalid memory. Try following command to check the dependencies:
$ find node_modules -iname "*.node"We've seen couple of similar reports earlier and after debugging these for long time I don't think these are caused by Vitest or Tinypool. It's simply the code that is run in
node:worker_threadsthat triggers the condition. In vitest-dev/vitest#3077 andtrpcit was seen that using NodeJS'sfetchinsidenode:worker_threadscan make the worker stuck and prevent it from terminating. In nodejs/undici#2026 there is a reproduction code snippet that is using only NodeJS's built-in modules.When you run into these cases in Vitest you could try to move the specific test case to be run in
node:child_processinstead: vitest-dev/vitest#2008 (comment). All other tests will still run innode:worker_threadsas fast as before.@fox1t if you end up finding a solution for this or to make a small reproduction case I'm happy to look into it.
Aslemammad commentedon Apr 14, 2023
@AriPerkkio Thank you so much for the explanation.
fox1t commentedon Apr 14, 2023
@AriPerkkio and @Aslemammad thank you both.
You pointed me in the right direction. Now I know the issue, but cannot reproduce it in isolation. First, our private codebase is complex (it is a monorepo), and this will likely not affect many other users.
The issue manifests when a Vitest mock of a
node_modulesdependency is also imported by other modules in the import chain.node_modulesDep.ModuleAimportsModuleBandnode_modulesDepModuleBimportsnode_modulesDepThe spawn of the worker thread for such a case is very slow, and after the test finishes, it goes into a seg fault.
As I said, I tried to reproduce it in isolation without success. So for the moment I used a mix of imports rework and poolMatchGlobs to make the tests pass.
If you have more ideas on how we can isolate it, I can make other tries.
Thanks again for your help!
Aslemammad commentedon Apr 14, 2023
Maybe you can ignore that file in the original vitest run, and spawn another vitest instance after finishing the original one which only runs that file!
jdmarshall commentedon Apr 29, 2023
One thing I've noticed with mocks is that starting in about Node 16, the timing of a synchronous return from an asynchronous method is different. I had to fix a couple of tests where I was relying on order of operations and it was causing issues.
I'm wondering if that's what you're seeing here.
AriPerkkio commentedon Apr 15, 2024
This should be fixed in Node v21: nodejs/node#51526
Feel free to open new issue with minimal reproduction case if you still run into this.