node Worker terminates with error in Mac OS

Worker terminates with error in Mac OS

Open sheremet-va opened this issue 1 year ago • 1 comments

Version

16.16.0

Platform

macOS 11.6.8 5 20G730

Subsystem

No response

What steps will reproduce the bug?

Examples in our CI:

https://github.com/vitest-dev/vitest/runs/7704223380?check_suite_focus=true
https://github.com/vitest-dev/vitest/runs/7685754161?check_suite_focus=true

After all tests are done, we are getting the error:

Assertion failed: (napi_create_external(env, fseenv, fse_environment_destroy, NULL, &result) == napi_ok), function fse_environment_create, file ../src/fsevents.c, line 87

I wasn't able to find this file in Node repo.

We are also getting Empty MaybeLocal error sometimes, which might be connected:

https://github.com/vitest-dev/vitest/runs/7685755871?check_suite_focus=true
https://github.com/vitest-dev/vitest/runs/7685757762?check_suite_focus=true

I am not able to reproduce it on smaller scale for now, unfortunately. It seems, there is some kind of race condition.

Code that fires up workers:

https://github.com/vitest-dev/vitest/blob/95c1d34368d799da417da219d394545ee83164e2/packages/vitest/src/node/pool.ts#L96

You can also notice that errors happen with "close with time out", this code is triggered here:

https://github.com/vitest-dev/vitest/blob/95c1d34368d799da417da219d394545ee83164e2/packages/vitest/src/node/core.ts#L436

I am able to reproduce it almost consistently in Vitest core tests:

Download Vitest repo (only node/reproduce branch is needed)
run

pnpm install
cd test/core
ppm run test

If you comment out this.pool?.close() (which is an async noop), you should see error less time. But I got a new error with it:

node[28013]: ../src/node_file-inl.h:160:virtual node::fs::FSReqPromise<node::AliasedBufferBase<double, v8::Float64Array, void> >::~FSReqPromise() [AliasedBufferT = node::AliasedBufferBase<double, v8::Float64Array, void>]: Assertion `finished_' failed.
 1: 0x102dd46e8 node::Abort() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 2: 0x102dd452c node::AppendExceptionLine(node::Environment*, v8::Local<v8::Value>, v8::Local<v8::Message>, node::ErrorHandlingMode) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 3: 0x102dd0e44 node::fs::FSReqPromise<node::AliasedBufferBase<double, v8::Float64Array, void> >::ResolveStat(uv_stat_t const*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 4: 0x102dd8e58 node::fs::FSReqAfterScope::~FSReqAfterScope() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 5: 0x102dd9310 node::fs::AfterOpenFileHandle(uv_fs_s*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 6: 0x103642bd4 uv__work_done [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 7: 0x103646370 uv__async_io [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 8: 0x1036580e8 uv__io_poll [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 9: 0x103646800 uv_run [/<root>/.nvm/versions/node/v16.16.0/bin/node]
10: 0x102d22ccc node::SpinEventLoop(node::Environment*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
11: 0x102e66df4 node::worker::Worker::Run() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
12: 0x102e6a01c node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::__invoke(void*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
13: 0x1a8a6026c _pthread_start [/usr/lib/system/libsystem_pthread.dylib]
14: 0x1a8a5b08c thread_start [/usr/lib/system/libsystem_pthread.dylib]

Run it a few times, if you don't see an error.

If I comment out this.close entirely, I get this error:

#
# Fatal error in , line 0
# Check failed: result.second.
#
#
#
#FailureMessage Object: 0x1763693a8
 1: 0x1008efff4 node::NodePlatform::GetStackTracePrinter()::$_3::__invoke() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 2: 0x101691dd0 V8_Fatal(char const*, ...) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 3: 0x100c76684 v8::internal::GlobalBackingStoreRegistry::Register(std::__1::shared_ptr<v8::internal::BackingStore>) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 4: 0x1009f2dbc v8::ArrayBuffer::GetBackingStore() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 5: 0x10086f9bc node::Buffer::Data(v8::Local<v8::Value>) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 6: 0x1008991b0 node::fs::Read(v8::FunctionCallbackInfo<v8::Value> const&) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 7: 0x100a4cea8 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 8: 0x100a4c9a0 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) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 9: 0x100a4c22c v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
10: 0x10118cd0c Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit [/<root>/.nvm/versions/node/v16.16.0/bin/node]
11: 0x101120858 Builtins_InterpreterEntryTrampoline [/<root>/.nvm/versions/node/v16.16.0/bin/node]
12: 0x10114fe54 Builtins_AsyncFunctionAwaitResolveClosure [/<root>/.nvm/versions/node/v16.16.0/bin/node]
13: 0x1011d4cf8 Builtins_PromiseFulfillReactionJob [/<root>/.nvm/versions/node/v16.16.0/bin/node]
14: 0x101142234 Builtins_RunMicrotasks [/<root>/.nvm/versions/node/v16.16.0/bin/node]
15: 0x10111e524 Builtins_JSRunMicrotasksEntry [/<root>/.nvm/versions/node/v16.16.0/bin/node]
16: 0x100aefe5c v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
17: 0x100af0290 v8::internal::(anonymous namespace)::InvokeWithTryCatch(v8::internal::Isolate*, v8::internal::(anonymous namespace)::InvokeParams const&) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
18: 0x100af037c v8::internal::Execution::TryRunMicrotasks(v8::internal::Isolate*, v8::internal::MicrotaskQueue*, v8::internal::MaybeHandle<v8::internal::Object>*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
19: 0x100b12fb8 v8::internal::MicrotaskQueue::RunMicrotasks(v8::internal::Isolate*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
20: 0x100b1384c v8::internal::MicrotaskQueue::PerformCheckpoint(v8::Isolate*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
21: 0x1007dddb4 node::InternalCallbackScope::Close() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
22: 0x1007dd7c4 node::InternalCallbackScope::~InternalCallbackScope() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
23: 0x10088c980 node::fs::FSReqPromise<node::AliasedBufferBase<double, v8::Float64Array, void> >::Resolve(v8::Local<v8::Value>) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
24: 0x100895194 node::fs::AfterStat(uv_fs_s*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
25: 0x1010febd4 uv__work_done [/<root>/.nvm/versions/node/v16.16.0/bin/node]
26: 0x101102370 uv__async_io [/<root>/.nvm/versions/node/v16.16.0/bin/node]
27: 0x1011140e8 uv__io_poll [/<root>/.nvm/versions/node/v16.16.0/bin/node]
28: 0x101102800 uv_run [/<root>/.nvm/versions/node/v16.16.0/bin/node]
29: 0x1007deccc node::SpinEventLoop(node::Environment*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
30: 0x100922df4 node::worker::Worker::Run() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
31: 0x10092601c node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::__invoke(void*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
32: 0x1a8a6026c _pthread_start [/usr/lib/system/libsystem_pthread.dylib]
33: 0x1a8a5b08c thread_start [/usr/lib/system/libsystem_pthread.dylib]

If I call pool.destroy() inside pool.close, I also get the error quite often:

FATAL ERROR: v8::ToLocalChecked Empty MaybeLocal.
 1: 0x1043206e8 node::Abort() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 2: 0x104320870 node::errors::TryCatchScope::~TryCatchScope() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 3: 0x104471dc4 v8::V8::ToLocalEmpty() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 4: 0x10431c9a0 node::fs::FSReqPromise<node::AliasedBufferBase<double, v8::Float64Array, void> >::Resolve(v8::Local<v8::Value>) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 5: 0x10432522c node::fs::AfterInteger(uv_fs_s*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 6: 0x104b8ebd4 uv__work_done [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 7: 0x104b92370 uv__async_io [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 8: 0x104ba40e8 uv__io_poll [/<root>/.nvm/versions/node/v16.16.0/bin/node]
 9: 0x104b92800 uv_run [/<root>/.nvm/versions/node/v16.16.0/bin/node]
10: 0x10426eccc node::SpinEventLoop(node::Environment*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
11: 0x1043b2df4 node::worker::Worker::Run() [/<root>/.nvm/versions/node/v16.16.0/bin/node]
12: 0x1043b601c node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::__invoke(void*) [/<root>/.nvm/versions/node/v16.16.0/bin/node]
13: 0x1a8a6026c _pthread_start [/usr/lib/system/libsystem_pthread.dylib]
14: 0x1a8a5b08c thread_start [/usr/lib/system/libsystem_pthread.dylib]

What do you see instead?

Cannot read properties of undefined (reading 'slice') 216

examples/vue test: Assertion failed: (napi_create_external(env, fseenv, fse_environment_destroy, NULL, &result) == napi_ok), function fse_environment_create, file ../src/fsevents.c, line 87. 218

Additional information

No response

Aug 06 '22 11:08 sheremet-va

Assertion failed: (napi_create_external(env, fseenv, fse_environment_destroy, NULL, &result) == napi_ok), function fse_environment_create, file ../src/fsevents.c, line 87 I wasn't able to find this file in Node repo.

It looks like this is from fsevents?

FSReqPromise errors

These may be fixed by nodejs/node#42910, which will be in Node.js v16.17.0. But I'm not sure.

Based on previous issues, it feels likely the race here is between the shutdown & the other actions trying to call into Javascript.

Aug 06 '22 18:08 kvakil

node node copied to clipboard