FATAL ERROR: v8::FromJust Maybe value is Nothing

[rozzilla]

Version

v20.18.0

Platform

Darwin N4V4PGFGPT 23.6.0 Darwin Kernel Version 23.6.0: Wed Jul 31 20:53:05 PDT 2024; root:xnu-10063.141.1.700.5~1/RELEASE_ARM64_T8112 arm64

Subsystem

No response

What steps will reproduce the bug?

Checkout the branch chore/node/v8-fatal-error-reproduction of this repo. Then:

• npm run setup
• npm run start

You'll get:

[14:28:51.817] INFO (31321): Starting the service "bug"...
FATAL ERROR: v8::FromJust Maybe value is Nothing
----- Native stack trace -----

 1: 0x104427d74 node::OnFatalError(char const*, char const*) ...

How often does it reproduce? Is there a required condition?

Always.

If you add a comment on the 2nd call to pino (line 6), it doesn't occur.

What is the expected behavior? Why is that the expected behavior?

Node should handle the shutdown differently, instead of throwing.

What do you see instead?

A stack trace of the error from v8

Additional information

I'm available to provide further information if this can help to fix the bug 😊

No response

[juanarbol]

Hi, thanks for the report.

Would you mind adding the whole backtrace? Also a smaller repro case would be handy; like a code snippet.

[rozzilla]

Hi, thanks for the report.

Hi @juanarbol 👋🏼

Would you mind adding the whole backtrace?

Here is the full log:

FATAL ERROR: v8::FromJust Maybe value is Nothing
----- Native stack trace -----

 1: 0x100cc7d74 node::OnFatalError(char const*, char const*)
 2: 0x100e58404 v8::api_internal::FromJustIsNothing()
 3: 0x100d7f89c node::worker::Worker::JoinThread()
 4: 0x100c69090 node::Environment::RunAndClearNativeImmediates(bool)::$_7::operator()(node::CallbackQueue<void, node::Environment*>*) const
 5: 0x100c68788 node::Environment::RunAndClearNativeImmediates(bool)
 6: 0x100c6ca50 node::Environment::InitializeLibuv()::$_1::__invoke(uv_async_s*)
 7: 0x1016a1b30 uv__async_io
 8: 0x1016b3c08 uv__io_poll
 9: 0x1016a20f4 uv_run
10: 0x100bf16f0 node::SpinEventLoopInternal(node::Environment*)
11: 0x100d7f3c0 node::worker::Worker::Run()
12: 0x100d82a1c node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::__invoke(void*)
13: 0x19bfd9f94 _pthread_start [/usr/lib/system/libsystem_pthread.dylib]
14: 0x19bfd4d34 thread_start [/usr/lib/system/libsystem_pthread.dylib]

Also a smaller repro case would be handy; like a code snippet.

The minimum repro case is documented above, I wasn't able to make it smaller 🤷🏼 You need to run node from this repo, following the instructions above.

[Qard]

Seems to be caused by the Check() on this object()->Set(...):

https://github.com/nodejs/node/blob/main/src/node_worker.cc#L457-L459

I'm not yet sure why. Maybe the object or context it belongs to is no longer valid at that point?

[Qard]

Strange...in this code:

object()->Set(env()->context(),
                  env()->message_port_string(),
                  Undefined(env()->isolate())).Check();

• object() is non-empty, and is not null or undefined
• env()->message_port_string() is a valid string with a value of "messagePort"
• Undefined(env()->isolate()) produces a valid undefined

And yet calling Set(...) on the object() fails 🤔

Doing v8::JSON::Stringify(...) on object() yields an empty maybe.

Seems like object() is somehow something it should not be, and I'm not sure yet what. 🤔

[Qard]

Seems to be triggering the immediate scheduled in StartThread after the thread is stopped, but also after the isolate is disposed, which seems like a race condition of some sort.

Worker(0:1034) Creating new worker instance with thread id 1
Worker(0:1034) Preparation for worker 1 finished
Worker(0:1034) Creating isolate for worker with id 1
Worker(0:1043) Creating new worker instance with thread id 2
Worker(0:1043) Preparation for worker 2 finished
Worker(0:1043) Creating isolate for worker with id 2
Worker(0:1034) Starting worker with id 1
Worker(0:1034) Worker 1 uses context from snapshot 1

Worker(0:1043) Starting worker with id 2
Worker(0:1043) Worker 2 uses context from snapshot 1

Worker(0:1034) Created Environment for worker with id 1
Worker(0:1034) Created message port for worker 1
Worker(0:1034) Loaded environment for worker 1
Worker(0:1043) Created Environment for worker with id 2
Worker(0:1043) Created message port for worker 2
Worker(0:1043) Loaded environment for worker 2
[20:52:29.821] INFO (55360): Starting the service "bug"...
Worker(2:1519) Creating new worker instance with thread id 3
Worker(2:1519) Preparation for worker 3 finished
Worker(2:1519) Creating isolate for worker with id 3
Worker(2:1526) Creating new worker instance with thread id 4
Worker(2:1526) Preparation for worker 4 finished
Worker(2:1526) Creating isolate for worker with id 4
Worker(2:1519) Starting worker with id 3
Worker(2:1519) Worker 3 uses context from snapshot 1

Worker(2:1526) Starting worker with id 4
Worker(2:1526) Worker 4 uses context from snapshot 1

Worker(2:1519) Created Environment for worker with id 3
Worker(2:1519) Created message port for worker 3
Worker(2:1519) Loaded environment for worker 3
Worker(2:1526) Created Environment for worker with id 4
Worker(2:1526) Created message port for worker 4
Worker(2:1526) Loaded environment for worker 4
Worker(2:1519) Worker 3 called Exit(0, (null), (null))
Worker(2:1519) Exiting thread for worker 3 with exit code 0
Worker(2:1519) Worker 3 thread stops
Worker(2:1519) Worker 3 dispose isolate
Worker(0:1043) Worker 2 called Exit(1, (null), (null))
Worker(2:1526) Worker 4 called Exit(0, (null), (null))
Worker(2:1519) In cleanup immediate for worker 3
Worker(2:1526) Exiting thread for worker 4 with exit code 0
Worker(2:1519) before
Worker(2:1519) object is empty: false
Worker(2:1519) json is empty: true
FATAL ERROR: v8::ToLocalChecked Empty MaybeLocal
----- Native stack trace -----

Worker(2:1526) Worker 4 thread stops
Worker(2:1526) Worker 4 dispose isolate
 1: 0x10413ce10 node::OnFatalError(char const*, char const*) [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 2: 0x1042f2330 v8::api_internal::ToLocalEmpty() [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 3: 0x10420f1e0 node::worker::Worker::JoinThread() [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 4: 0x1040d2f10 node::Environment::RunAndClearNativeImmediates(bool)::$_0::operator()(node::CallbackQueue<void, node::Environment*>*) const [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 5: 0x1040d25c0 node::Environment::RunAndClearNativeImmediates(bool) [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 6: 0x1040d6bc0 node::Environment::InitializeLibuv()::$_0::__invoke(uv_async_s*) [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 7: 0x104ba5754 uv__async_io [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 8: 0x104bb83fc uv__io_poll [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
 9: 0x104ba5cbc uv_run [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
10: 0x104054ac4 node::SpinEventLoopInternal(node::Environment*) [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
11: 0x10420eb20 node::worker::Worker::Run() [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
12: 0x1042121f8 node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_0::__invoke(void*) [/Users/stephenbelanger/Code/cpp/node/out/Release/node]
13: 0x18e1932e4 _pthread_start [/usr/lib/system/libsystem_pthread.dylib]
14: 0x18e18e0fc thread_start [/usr/lib/system/libsystem_pthread.dylib]
zsh: abort      NODE_DEBUG_NATIVE=worker ../../cpp/node/node ./node_modules/.bin/wattpm start

Note the In cleanup immediate for worker 3, which I added to test and match that up with other worker 3 lines.

[targos]

I don't know why this is happening, but the code is not safe.
At this point we are not allowed to call into JS, which v8::Object::Set may do.

[Qard]

Yeah. That would seem to be the case. Not sure why we're doing this here an not somewhere else? Or if we even need to do it at all if the thread is getting disposed anyway?

[Qard]

This issues seems not to reproduce on v22+. It appears to be a race condition though, so I've opened a PR (#56191) anyway, which is not exactly a fix per se, but at least would ensure that particular crash doesn't happen again. Quite possibly deeper issues in there though as there seems to be a lack of thread coordination between the worker teardown paths.