Repository navigation
test-worker-cleanexit-with-moduleload crashing on multiple platforms in CI #39036
Description
Activity
Still occurring
- alpine-latest
also
test-worker-cleanexit-with-js@nodejs/workers
@nodejs/workers
Although I guess this isn't exactly a worker threads test. From Gireesh's commit message introducing the test:
Execute many module loads in worker in a loop
while exiting from the main thread at arbitrary
execution points, and make sure that the workers
quiesce without crashing.worker_threadsare not necessarily the subject of
testing, those are used for easy simulation of
multi-thread scenarios.I can replicate locally (on macOS) by just repeating the test many times:
tools/test.py --repeat=1024 test/parallel/test-worker-cleanexit-with-moduleload.js === release test-worker-cleanexit-with-moduleload === Path: parallel/test-worker-cleanexit-with-moduleload Command: out/Release/node /Users/trott/io.js/test/parallel/test-worker-cleanexit-with-moduleload.js --- CRASHED (Signal: 11) --- === release test-worker-cleanexit-with-moduleload === Path: parallel/test-worker-cleanexit-with-moduleload Command: out/Release/node /Users/trott/io.js/test/parallel/test-worker-cleanexit-with-moduleload.js --- CRASHED (Signal: 11) --- === release test-worker-cleanexit-with-moduleload === Path: parallel/test-worker-cleanexit-with-moduleload Command: out/Release/node /Users/trott/io.js/test/parallel/test-worker-cleanexit-with-moduleload.js --- CRASHED (Signal: 11) --- === release test-worker-cleanexit-with-moduleload === Path: parallel/test-worker-cleanexit-with-moduleload Command: out/Release/node /Users/trott/io.js/test/parallel/test-worker-cleanexit-with-moduleload.js --- CRASHED (Signal: 11) --- === release test-worker-cleanexit-with-moduleload === Path: parallel/test-worker-cleanexit-with-moduleload Command: out/Release/node /Users/trott/io.js/test/parallel/test-worker-cleanexit-with-moduleload.js --- CRASHED (Signal: 11) --- [08:10|% 100|+ 1019|- 5]: Done $
Here's the information about the crashed thread from the diagnostic log:
Thread 13 Crashed: 0 node 0x000000010d859610 node::EnabledDebugList::enabled(node::DebugCategory) const + 0 (debug_utils.h:66) [inlined] 1 node 0x000000010d859610 void node::Debug<>(node::AsyncWrap*, char const*) + 8 (debug_utils-inl.h:194) [inlined] 2 node 0x000000010d859610 node::worker::MessagePort::OnMessage(node::worker::MessagePort::MessageProcessingMode) + 48 (node_messaging.cc:728) 3 node 0x000000010e20015b uv__async_io + 379 (async.c:163) 4 node 0x000000010e2139ac uv__io_poll + 2028 (kqueue.c:375) 5 node 0x000000010e200651 uv_run + 417 (core.c:385) 6 node 0x000000010d7b8ac9 node::Environment::CleanupHandles() + 377 (env.cc:645) 7 node 0x000000010d7b8eca node::Environment::RunCleanup() + 314 (env.cc:677) 8 node 0x000000010d755f01 node::FreeEnvironment(node::Environment*) + 113 (environment.cc:372) 9 node 0x000000010d8b744e node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))>::operator()(node::Environment*) const + 8 (util.h:636) [inlined] 10 node 0x000000010d8b744e std::__1::unique_ptr<node::Environment, node::FunctionDeleter<node::Environment, &(node::FreeEnvironment(node::Environment*))> >::reset(node::Environment*) + 8 (memory:2623) [inlined] 11 node 0x000000010d8b744e node::worker::Worker::Run()::$_0::operator()() const + 68 (node_worker.cc:284) [inlined] 12 node 0x000000010d8b744e node::OnScopeLeaveImpl<node::worker::Worker::Run()::$_0>::~OnScopeLeaveImpl() + 68 (util.h:527) [inlined] 13 node 0x000000010d8b744e node::OnScopeLeaveImpl<node::worker::Worker::Run()::$_0>::~OnScopeLeaveImpl() + 68 (util.h:527) [inlined] 14 node 0x000000010d8b744e node::worker::Worker::Run() + 990 (node_worker.cc:350) 15 node 0x000000010d8baff2 node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::operator()(void*) const + 25 (node_worker.cc:596) [inlined] 16 node 0x000000010d8baff2 node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::$_3::__invoke(void*) + 50 (node_worker.cc:585) 17 libsystem_pthread.dylib 0x00007fff205d18fc _pthread_start + 224 18 libsystem_pthread.dylib 0x00007fff205cd443 thread_start + 15 Thread 13 crashed with X86 Thread State (64-bit): rax: 0x00007fb6058af480 rbx: 0x0000000000000000 rcx: 0x00000000058af4c0 rdx: 0x000070000fc091b0 rdi: 0x00007fb603e658e0 rsi: 0x0000000000000000 rbp: 0x000070000fc091a0 rsp: 0x000070000fc090c0 r8: 0x00000000000000c7 r9: 0x000070000fc09600 r10: 0x00007fb604008800 r11: 0x0000000000000246 r12: 0x00007fb603e659b0 r13: 0x00007fb603e65948 r14: 0x000070000fc11af8 r15: 0x00007fb603e658e0 rip: 0x000000010d859610 rfl: 0x0000000000000206 cr2: 0x000024d14b64c000 Logical CPU: 0 Error Code: 0x00000000 Trap Number: 221 Thread 13 instruction stream not available. Thread 13 last branch register state not available.Reacted by Gireesh Punathilreproduced on a linux bare metal with the latest.
here is my crash scenario:
(gdb) where #0 0x00000000010ae5c3 in v8::internal::JSReceiver::GetCreationContext() () #1 0x0000000000d155c8 in v8::Object::GetCreationContext() () #2 0x0000000000b6cab3 in node::worker::MessagePort::OnMessage(node::worker::MessagePort::MessageProcessingMode) () #3 0x00000000015b37f6 in uv__async_io (loop=0x7f75d3ffea98, w=<optimized out>, events=<optimized out>) at ../deps/uv/src/unix/async.c:163 #4 0x00000000015c6576 in uv__io_poll (loop=loop@entry=0x7f75d3ffea98, timeout=<optimized out>) at ../deps/uv/src/unix/linux-core.c:462 #5 0x00000000015b4128 in uv_run (loop=0x7f75d3ffea98, mode=UV_RUN_ONCE) at ../deps/uv/src/unix/core.c:385 #6 0x0000000000aa9550 in node::Environment::CleanupHandles() () #7 0x0000000000ab67cb in node::Environment::RunCleanup() () #8 0x0000000000a668e9 in node::FreeEnvironment(node::Environment*) () #9 0x0000000000be8e91 in node::worker::Worker::Run() () #10 0x0000000000be93d8 in node::worker::Worker::StartThread(v8::FunctionCallbackInfo<v8::Value> const&)::{lambda(void*)#1}::_FUN(void*) () #11 0x00007f75f438814a in start_thread () from /lib64/libpthread.so.0 #12 0x00007f75f40b7dc3 in clone () from /lib64/libc.so.6 (gdb)
(gdb) x/5i _ZN2v88internal10JSReceiver18GetCreationContextEv 0x10ae5c0 <_ZN2v88internal10JSReceiver18GetCreationContextEv>: mov rdx,QWORD PTR [rdi] => 0x10ae5c3 <_ZN2v88internal10JSReceiver18GetCreationContextEv+3>: mov rcx,QWORD PTR [rdx-0x1] 0x10ae5c7 <_ZN2v88internal10JSReceiver18GetCreationContextEv+7>: mov rax,QWORD PTR [rcx+0x1f] 0x10ae5cb <_ZN2v88internal10JSReceiver18GetCreationContextEv+11>: test al,0x1 0x10ae5cd <_ZN2v88internal10JSReceiver18GetCreationContextEv+13>: jne 0x10ae620 <_ZN2v88internal10JSReceiver18GetCreationContextEv+96> (gdb) i r rdi rdi 0x7f75d3ffaf48 140144044650312From this and the one which @Trott captured earlier, it is evident that we are shutting down the worker (
node::Environment::RunCleanup()), but thelibuvis seen is actively executing callbacks (node::worker::MessagePort::OnMessage). Is this expected? Has anything changed in this area recently?@gireeshpunathil Can you figure out why it is crashing in
GetCreationContext()? I think that’s the interesting bit here.but the
libuvis seen is actively executing callbacks (node::worker::MessagePort::OnMessage).That would be surprising, yes, but I’m not sure if we should really consider it illegal (unless the
uv_close()callback has already been invoked by libuv)node/deps/v8/src/objects/js-objects.cc
Line 543 in 82b44f4
@addaleax - the dereferencing is what is crashing, because the
thispointer is not valid.sorry, I may be wrong here too; let me dig a little more.
(gdb) x/2i 0x10ae5c0 // JSReceiver receiver = *this; 0x10ae5c0 <v8::internal::JSReceiver::GetCreationContext>: mov rdx,QWORD PTR [rdi] // Get the vft for the `receiver` object, crash => 0x10ae5c3 <v8::internal::JSReceiver::GetCreationContext+3>: mov rcx,QWORD PTR [rdx-0x1]
so it is not the
this, but thereceiverobject, that is corrupt:(gdb) i r rdi rdi 0x7fcae6bf5f48 140509431422792 (gdb) x/2x 0x7fcae6bf5f48 0x7fcae6bf5f48: 0x00070001 0x00050004 (gdb) x/w 0x0005000400070000 0x5000400070000: Cannot access memory at address 0x5000400070000
@addaleax - does it throw any hint?
@gireeshpunathil Well – it probably means that the JS object associated with the
MessagePorthas already been garbage collected at that point, or the handle we hold to it has been destroyed (which would happen before the former anyway). But that only happens in theuv_close()callback, so I guess the important question is: Is libuv sending messages to anuv_async_tifuv_close()has already been called on it?Reacted by Gireesh PunathilIf you are referring to
uv_async_sendoruv__async_send, those do not check the handle status , and assume that those are good. But is safe to rely on these primitives to manage such a race? Or should we do such a check in the first async callback (in this casenode::worker::MessagePort::OnMessage) and abandon the propagation if we are in the cleanup phase?or are you thinking that this is not a worker-specific issue, but a wider issue with the libuv itself?
If you are referring to
uv_async_sendoruv__async_send, those do not check the handle status , and assume that those are good.I think this is expected.
But is safe to rely on these primitives to manage such a race?
I don’t understand this question, tbh. Which race? Which primitives?
Or should we do such a check in the first async callback (in this case
node::worker::MessagePort::OnMessage) and abandon the propagation if we are in the cleanup phase?Again, not sure what “such a check” or “first async callback” refer to, but for the second part, no, we should rely on the fact that we should not be receiving callbacks from libuv after having fully closed the handle, because if that wasn’t true that would be unsafe behavior on libuv’s end anyway.
or are you thinking that this is not a worker-specific issue, but a wider issue with the libuv itself?
Maybe? That’s what my question above was focused on finding out.
I don’t understand this question, tbh. Which race? Which primitives?
let me explain my understanding of the issue. I am not claiming complete comprehension of it, only trying to make meaning out of the callstack at the failing site.
In
Environment::CleanupHandles()weinitiateclose of handles. I say initiate, becauseuv_closeis asynchronous.Lines 635 to 636 in 1bbe66f
This makes sure any subsequent message handling will not progress, as we don't send anything if the handles are closed or closing:
Lines 625 to 628 in bcf73d6
Then we run uv_run. There, we handle events, potentially on closed / closing handles, (due to the asynchrony of the
uv_close). We progress on callbacks with bad stuff and crash.does it sound reasonable to you?
3 remaining items
@gireeshpunathil Yeah, that does answer it – but it’s worrying. How hard is it to reproduce this for you? Would you be able to make the test crash while running unter valgrind?
Reacted by Gireesh Punathil@addaleax - sure. usually it crashes like once in ten runs or so, so not hard at all. will try with valgrind.
@addaleax - I tried doing a bisect, but got inconclusive and contradicting results (mostly because the failure is not deterministic), so deeming it as non-trustworthy, and not posting here.
I am taking another approach of unwinding the history of
src/node_messaging.ccand doing a manual trial and error. Right now I am suspecting bcf73d6 , but I should admit that I did not follow the valgrind report, other than that we destroyed transferrable objects after deserializing messages, and those objects were accessed in the callbacks.- added a commit that references this issue
on Jul 19, 2021 other than that we destroyed transferrable objects after deserializing messages, and those objects were accessed in the callbacks.
@gireeshpunathil Thanks, the valgrind report looks very helpful. In particular, we can tell from the valgrind report that the problem is that a MessagePort object was deleted while it was being transferred to another MessagePort that was unable to deserialize the message as a whole (because the worker was shutting down, I presume). That should not be happening – the transferred MessagePort should be closed, not outright deleted.
I’ve opened a potential fix based on this in #39441 (but haven’t confirmed that it actually fixes this issue here). Thank you for the helpful debugging!
Reacted by Gireesh Punathil@addaleax - that is very nice, thanks!
So what you are saying is that a MessagePort should not be deleted outright if the transfer fails; what if the transfer succeeds? Does the new MessagePort created (the deserialized copy) makes the old one safe to delete? What causes the stale objects to escape into libuv? I have still a gap in my understanding here, it would be great if you can fill me up.
So what you are saying is that a MessagePort should not be deleted outright if the transfer fails
👍
what if the transfer succeeds? Does the new MessagePort created (the deserialized copy) makes the old one safe to delete?
There’s no copy, that’s the point of transfering (as opposed to cloning). :) If the transfer succeeds, there’s a new
MessagePortobject on the receiving side – but that’s fine, because then the receiving side can manage its lifetime like any otherMessagePort.What causes the stale objects to escape into libuv?
I’m not sure what you mean by ‘escape’ – the receiving side creates a
MessagePortobject, which has an embeddeduv_async_t, which is initialized and registered with libuv. The problem is that there is nouv_close()call that would tell libuv to un-register it again when it is clear that receiving theMessagePortwill fail.I have still a gap in my understanding here, it would be great if you can fill me up.
I guess it might help to draw out the timeline of events in the crashing case:
- Thread A and B are connected by a messaging channel, and thread A also owns another messaging channel consisting of MessagePorts X and Y
- Thread A sends X instance to B over their common channel
- Thread B starts receiving the message, and creates a
MessagePortinstance because the deserialized message contains one, taking over the state from X - Thread B is terminated by thread A
- Thread A sends a message from Y to X
- Thread B sees that deserialization is failing because it’s terminating, and starts deleting all objects in the received message that would otherwise leak memory
- Thread B deletes the
MessagePortit created in step 3 (but does not close it) - Thread B sees the message sent in step 7 on the event loop, and tries to deliver it to X
- Boom
Reacted by Benjamin GruenbaumReacted by Gireesh Punathil and Preveen Pok, thanks @addaleax for the detailed explanation, this is really useful!
Reacted by Anna Henningsen- added a commit that references this issue
on Jul 25, 2021 - added a commit that references this issue
on Jul 29, 2021 - added a commit that references this issue
on Sep 4, 2021 - added a commit that references this issue
on May 22, 2026
https://ci.nodejs.org/job/node-test-binary-arm-12+/11278/RUN_SUBSET=0,label=pi2-docker/console
https://ci.nodejs.org/job/node-test-commit-linux/41808/nodes=debian10-x64/console