worker: fix stream & termination race bug #42874

airtable-keyhanvakil · 2022-04-26T03:55:09Z

OnStreamAfterReqFinished uses v8::Object::Has to check if it needs
to call oncomplete. v8::Object::Has needs to execute Javascript.
However when worker threads are involved, OnStreamAfterReqFinished may
be called after the worker thread termination has begun via
worker.terminate(). This makes v8::Object::Has return Nothing,
which triggers an assert.

This diff fixes the issue by checking env->is_stopping() first.

Fixes: #38418

`OnStreamAfterReqFinished` uses `v8::Object::Has` to check if it needs to call `oncomplete`. `v8::Object::Has` needs to execute Javascript. However when worker threads are involved, `OnStreamAfterReqFinished` may be called after the worker thread termination has begun via `worker.terminate()`. This makes `v8::Object::Has` return `Nothing`, which triggers an assert. This diff fixes the issue by simply defaulting us to `false` in the case where `Nothing` is returned. This is sound because we can't execute `oncomplete` anyway as the isolate is terminating. Fixes: nodejs#38418

airtable-keyhanvakil · 2022-04-26T03:58:28Z

I used the repro in the referenced issue: https://github.com/Prinzhorn/electron-sigabrt

Here's the backtrace on a debug build & also some GDB output:

(gdb) bt
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
#1  0x00007f2bab11a859 in __GI_abort () at abort.c:79
#2  0x0000564469142bfd in node::Abort () at ../src/node_errors.cc:260
#3  0x0000564469143b32 in node::OnFatalError (location=0x56446b25644a "v8::FromJust",
    message=0x56446b256432 "Maybe value is Nothing.") at ../src/node_errors.cc:450
#4  0x000056446941deff in v8::Utils::ReportApiFailure (
    location=0x56446b25644a "v8::FromJust", message=0x56446b256432 "Maybe value is Nothing.")
    at ../deps/v8/src/api/api.cc:296
#5  0x0000564468fe35b9 in v8::Maybe<bool>::FromJust (this=0x7f2ba88ebeb6)
    at ../deps/v8/include/v8.h:10469
#6  0x00005644692b5bea in node::ReportWritesToJSStreamListener::OnStreamAfterReqFinished (
    this=0x7f2b94414730, req_wrap=0x7f2b94320590, status=0) at ../src/stream_base.cc:603
#7  0x00005644692b5c87 in node::ReportWritesToJSStreamListener::OnStreamAfterWrite (
    this=0x7f2b94414730, req_wrap=0x7f2b94320590, status=0) at ../src/stream_base.cc:609
#8  0x00005644692b5e81 in node::StreamListener::OnStreamAfterWrite (this=0x7f2b94414828,
    w=0x7f2b94320590, status=0) at ../src/stream_base.cc:639
#9  0x00005644692b641f in node::StreamResource::EmitAfterWrite (this=0x7f2b94414708,
    w=0x7f2b94320590, status=0) at ../src/stream_base-inl.h:108
#10 0x00005644692b5d32 in node::WriteWrap::OnDone (this=0x7f2b94320590, status=0)
    at ../src/stream_base.cc:623
#11 0x00005644690c7786 in node::StreamReq::Done (this=0x7f2b94320590, status=0, error_str=0x0)
    at ../src/stream_base-inl.h:288
#12 0x0000564469175df0 in node::http2::Http2Session::ClearOutgoing (this=0x7f2b942f1ef0,
    status=-16) at ../src/node_http2.cc:1616
#13 0x000056446917667d in node::http2::Http2Session::SendPendingData (this=0x7f2b942f1ef0)
    at ../src/node_http2.cc:1736
#14 0x0000564469175907 in node::http2::Http2Session::<lambda(node::Environment*)>::operator()(node::Environment *) const (__closure=0x7f2b94310268, env=0x7f2b9414af60)
    at ../src/node_http2.cc:1582
#15 0x000056446919529b in node::CallbackQueue<void, node::Environment*>::CallbackImpl<node::http2::Http2Session::MaybeScheduleWrite()::<lambda(node::Environment*)> >::Call(node::Environment *) (this=0x7f2b94310250, args#0=0x7f2b9414af60) at ../src/callback_queue-inl.h:90
#16 0x000056446906c170 in node::Environment::<lambda(node::Environment::NativeImmediateQueue*)>::operator()(node::Environment::NativeImmediateQueue *) const (__closure=0x7f2ba88ec5d0,
    queue=0x7f2b9414b8f0) at ../src/env.cc:764
#17 0x000056446906c384 in node::Environment::RunAndClearNativeImmediates (
    this=0x7f2b9414af60, only_refed=false) at ../src/env.cc:777
#18 0x000056446906cbfa in node::Environment::CheckImmediate (handle=0x7f2b9414b1b0)
    at ../src/env.cc:917
#19 0x000056446a23ec2c in uv__run_check (loop=0x7f2ba88eca28)
    at ../deps/uv/src/unix/loop-watcher.c:67
#20 0x000056446a2341ed in uv_run (loop=0x7f2ba88eca28, mode=UV_RUN_DEFAULT)
    at ../deps/uv/src/unix/core.c:398
#21 0x0000564468fd87fe in node::SpinEventLoop (env=0x7f2b9414af60)
    at ../src/api/embed_helpers.cc:36
#22 0x000056446928c3c8 in node::worker::Worker::Run (this=0x56446f1184a0)
    at ../src/node_worker.cc:344
#23 0x000056446928e38b in node::worker::Worker::<lambda(void*)>::operator()(void *) const (
    __closure=0x0, arg=0x56446f1184a0) at ../src/node_worker.cc:612
(gdb) p env->isolate()->IsExecutionTerminating()
$27 = true

RaisinTen

Would it be possible to add a test?

However when worker threads are involved, OnStreamAfterReqFinished may
be called after the worker thread termination has begun via
worker.terminate(). This makes v8::Object::Has return Nothing,
which triggers an assert.

Why would calling this function after worker.terminate() return Nothing?

src/stream_base.cc

airtable-keyhanvakil · 2022-04-26T16:57:09Z

Would it be possible to add a test?

Possibly. The repro only crashes rarely (something like 1% of the time
on my system). The exact conditions are somewhat rare: the
worker.terminate in the main thread needs to interleave in a specific
way with the worker thread's execution. Are you aware of any similar
tests that have similar needs so I could copy from them?

However when worker threads are involved, OnStreamAfterReqFinished may
be called after the worker thread termination has begun via
worker.terminate(). This makes v8::Object::Has return Nothing,
which triggers an assert.

Why would calling this function after worker.terminate() return Nothing?

Because v8::Object::Has uses this macro:

ENTER_V8(isolate, context, Object, Has, Nothing<bool>(), i::HandleScope);

which in turn uses this macro:

#define ENTER_V8_HELPER_DO_NOT_USE(isolate, context, class_name,  \
                                   function_name, bailout_value,  \
                                   HandleScopeClass, do_callback) \
  if (IsExecutionTerminatingCheck(isolate)) {                     \
    return bailout_value;                                         \
  }                                                               \
...

and worker.terminate() makes IsExecutionTerminatingCheck(isolate)
true.

airtable-keyhanvakil · 2022-04-28T07:04:17Z

OK. I was able to add a test. On my machine, it fails 100/100 times
without this patch and 0/100 times with the patch.

I styled this after some of the other "terminate" tests. cc @addaleax as
it looks like you wrote a lot of these tests and may have opinions.

RaisinTen · 2022-04-30T14:50:48Z

Because v8::Object::Has uses this macro:

ENTER_V8(isolate, context, Object, Has, Nothing<bool>(), i::HandleScope);

which in turn uses this macro:

#define ENTER_V8_HELPER_DO_NOT_USE(isolate, context, class_name,  \
                                   function_name, bailout_value,  \
                                   HandleScopeClass, do_callback) \
  if (IsExecutionTerminatingCheck(isolate)) {                     \
    return bailout_value;                                         \
  }                                                               \
...

and worker.terminate() makes IsExecutionTerminatingCheck(isolate) true.

Right - I mean what exception is causing this? IsExecutionTerminatingCheck() would return true only if there is an exception scheduled to be thrown.

node/deps/v8/src/api/api-inl.h

Lines 236 to 242 in 02e0c17

    
           inline bool IsExecutionTerminatingCheck(i::Isolate* isolate) { 
        
             if (isolate->has_scheduled_exception()) { 
        
               return isolate->scheduled_exception() == 
        
                      i::ReadOnlyRoots(isolate).termination_exception(); 
        
             } 
        
             return false; 
        
           }

OK. I was able to add a test. On my machine, it fails 100/100 times without this patch and 0/100 times with the patch.

I'm not able to reproduce the crash locally with this test. 🤔

airtable-keyhanvakil · 2022-05-02T21:33:19Z

Because v8::Object::Has uses this macro:
ENTER_V8(isolate, context, Object, Has, Nothing<bool>(), i::HandleScope);
which in turn uses this macro:
#define ENTER_V8_HELPER_DO_NOT_USE(isolate, context, class_name,  \
                                   function_name, bailout_value,  \
                                   HandleScopeClass, do_callback) \
  if (IsExecutionTerminatingCheck(isolate)) {                     \
    return bailout_value;                                         \
  }                                                               \
...
and worker.terminate() makes IsExecutionTerminatingCheck(isolate) true.
Right - I mean what exception is causing this? IsExecutionTerminatingCheck() would return true only if there is an exception scheduled to be thrown.

My thoughts were that the current flow is something like this:

Main thread calls worker.terminate, which invokes stopThread -> Worker::StopThread -> Worker::Exit -> Stop(env) -> Environment::ExitEnv -> Isolate::TerminateExecution.

node/lib/internal/worker.js

Line 360 in ce29d28

this[kHandle].stopThread();

node/deps/v8/src/api/api.cc

Line 8499 in ce29d28

isolate->stack_guard()->RequestTerminateExecution();
Worker thread eventually hits a stack guard which invokes internal::Isolate::TerminateExecution

node/deps/v8/src/execution/stack-guard.cc

Line 288 in ce29d28

return isolate_->TerminateExecution();
That throws terminate_exception, which is the thing that IsExecutionTerminatingCheck is checking:

node/deps/v8/src/execution/isolate.cc

Line 1611 in ce29d28

Object Isolate::TerminateExecution() {

So I think the answer to your question is "the terminate_exception".

I suppose another option here would be to check env->can_call_into_js as suggested in the README: https://github.com/nodejs/node/blob/master/src/README.md#calling-into-javascript

OK. I was able to add a test. On my machine, it fails 100/100 times without this patch and 0/100 times with the patch.

I'm not able to reproduce the crash locally with this test. 🤔

Can you share what system you are on? For me, that test case reproduces 100% of the time on both a 2019 Macbook Pro (MacBookPro16,1 running Big Sur 11.6) and a cloud VM (AWS m5a.2xlarge, Ubuntu 20.04.3 LTS, Linux version 5.11.0-1027-aws). (It does seem to be pretty timing-dependent so looping could help with flakiness -- if I do it while ninja is compiling, it drops to only reproducing ~70% of the time.)

RaisinTen

Thanks for elaborating! This seems like the same case as #42910.

Can you share what system you are on?

I had initially tested this on my Intel MBP running Monterey 12.3.1 and later on Ubuntu 20.04 running on Parallels Linux because I saw your GDB logs and assumed that you were on Linux.

I have suggested a test that crashes on all of these platforms consistently.

src/stream_base.cc

test/parallel/test-worker-http2-stream-terminate.js

airtable-keyhanvakil · 2022-05-03T16:58:50Z

Thank you for the suggestions! I pasted the test code in & changed to use env->is_stopping() instead.

RaisinTen

LGTM

RaisinTen · 2022-05-04T12:26:32Z

@addaleax PTAL.

nodejs-github-bot · 2022-05-04T14:52:18Z

CI: https://ci.nodejs.org/job/node-test-pull-request/43878/

airtable-keyhanvakil · 2022-05-05T00:38:08Z

So it looks like the two CI builds both failed on the new test with a timeout:

Any thoughts here? it takes much less than 2 minutes on my system, but I suppose there's a lot of contention in CI:

$ time ./node test/parallel/test-worker-http2-stream-terminate.js 

real    0m10.303s
user    0m25.510s
sys     0m3.807s

nodejs-github-bot · 2022-05-05T11:46:20Z

CI: https://ci.nodejs.org/job/node-test-pull-request/43891/

RaisinTen · 2022-05-05T16:23:04Z

I think you could try to quit the process in a setTimeout() based on the timeout value returned by common.platformTimeout() but maybe there's a better way. @richardlau could you please confirm?

richardlau · 2022-05-05T16:32:41Z

So it looks like the two CI builds both failed on the new test with a timeout:

https://ci.nodejs.org/job/node-test-commit-custom-suites-freestyle/25122/testReport/junit/(root)/test/parallel_test_worker_http2_stream_terminate/

https://ci.nodejs.org/job/node-test-commit-custom-suites-freestyle/25114/testReport/junit/(root)/test/parallel_test_worker_http2_stream_terminate/

Any thoughts here? it takes much less than 2 minutes on my system, but I suppose there's a lot of contention in CI:
$ time ./node test/parallel/test-worker-http2-stream-terminate.js 

real    0m10.303s
user    0m25.510s
sys     0m3.807s

https://ci.nodejs.org/job/node-test-commit-custom-suites-freestyle/ URLs are going to be the tests that run in Worker threads, so you'll want to try with

 ./tools/test.py --worker parallel/test-worker-http2-stream-terminate

airtable-keyhanvakil · 2022-05-05T23:26:14Z

So it looks like the two CI builds both failed on the new test with a timeout:

https://ci.nodejs.org/job/node-test-commit-custom-suites-freestyle/25122/testReport/junit/(root)/test/parallel_test_worker_http2_stream_terminate/

https://ci.nodejs.org/job/node-test-commit-custom-suites-freestyle/25114/testReport/junit/(root)/test/parallel_test_worker_http2_stream_terminate/

Any thoughts here? it takes much less than 2 minutes on my system, but I suppose there's a lot of contention in CI:
$ time ./node test/parallel/test-worker-http2-stream-terminate.js 

real    0m10.303s
user    0m25.510s
sys     0m3.807s
https://ci.nodejs.org/job/node-test-commit-custom-suites-freestyle/ URLs are going to be the tests that run in Worker threads, so you'll want to try with
 ./tools/test.py --worker parallel/test-worker-http2-stream-terminate

Thanks, that did it. I cribbed the HAS_STARTED_WORKER pattern from the other tests in this [e: directory]. Presumably the same sort of pattern needs to be applied to #42910.

nodejs-github-bot · 2022-05-06T12:51:29Z

CI: https://ci.nodejs.org/job/node-test-pull-request/43900/

nodejs-github-bot · 2022-05-06T15:44:08Z

CI: https://ci.nodejs.org/job/node-test-pull-request/43904/

nodejs-github-bot · 2022-05-06T22:01:05Z

Landed in 0fc1cf4

`OnStreamAfterReqFinished` uses `v8::Object::Has` to check if it needs to call `oncomplete`. `v8::Object::Has` needs to execute Javascript. However when worker threads are involved, `OnStreamAfterReqFinished` may be called after the worker thread termination has begun via `worker.terminate()`. This makes `v8::Object::Has` return `Nothing`, which triggers an assert. This diff fixes the issue by simply defaulting us to `false` in the case where `Nothing` is returned. This is sound because we can't execute `oncomplete` anyway as the isolate is terminating. Fixes: #38418 PR-URL: #42874 Reviewed-By: Darshan Sen <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Antoine du Hamel <[email protected]>

airtable-keyhanvakil · 2022-07-06T18:01:16Z

Somebody in #43304 asked if this could be backported to earlier releases (v14 / v16). I think that is a good idea. I am not sure how that process works, but it seems like this bug fix would cherry-pick cleanly onto those branches. How can I get these changes backported?

aduh95 · 2022-07-06T19:15:19Z

node/doc/contributing/backporting-to-release-lines.md

Lines 19 to 25 in a0440c9

    
           ## What can be backported? 
        
           The "Current" release line is much more lenient than the LTS release lines in 
        
           what can be landed. Our LTS release lines (see the [Release Plan][]) 
        
           require that commits mature in the Current release for at least 2 weeks before 
        
           they can be landed in an LTS staging branch. Only after "maturation" will those 
        
           commits be cherry-picked or backported.

It should be included in the next version of Node.js 16.x without any action from you; regarding v14.x, it's in maintenance mode so it won't land there unless someone opens a backport PR to v14.x-staging. The process for doing that is explained at https://github.com/nodejs/node/blob/main/doc/contributing/backporting-to-release-lines.md#how-to-submit-a-backport-pull-request.

`OnStreamAfterReqFinished` uses `v8::Object::Has` to check if it needs to call `oncomplete`. `v8::Object::Has` needs to execute Javascript. However when worker threads are involved, `OnStreamAfterReqFinished` may be called after the worker thread termination has begun via `worker.terminate()`. This makes `v8::Object::Has` return `Nothing`, which triggers an assert. This diff fixes the issue by simply defaulting us to `false` in the case where `Nothing` is returned. This is sound because we can't execute `oncomplete` anyway as the isolate is terminating. Fixes: #38418 PR-URL: #42874 Reviewed-By: Darshan Sen <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Antoine du Hamel <[email protected]>

`OnStreamAfterReqFinished` uses `v8::Object::Has` to check if it needs to call `oncomplete`. `v8::Object::Has` needs to execute Javascript. However when worker threads are involved, `OnStreamAfterReqFinished` may be called after the worker thread termination has begun via `worker.terminate()`. This makes `v8::Object::Has` return `Nothing`, which triggers an assert. This diff fixes the issue by simply defaulting us to `false` in the case where `Nothing` is returned. This is sound because we can't execute `oncomplete` anyway as the isolate is terminating. Fixes: nodejs/node#38418 PR-URL: nodejs/node#42874 Reviewed-By: Darshan Sen <[email protected]> Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Antoine du Hamel <[email protected]>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. needs-ci PRs that need a full CI run. labels Apr 26, 2022

RaisinTen reviewed Apr 26, 2022

View reviewed changes

src/stream_base.cc Outdated Show resolved Hide resolved

add test

cf200b5

airtable-keyhanvakil force-pushed the fix-stream-worker-terminate branch from ce6ca47 to cf200b5 Compare April 28, 2022 07:01

lint

c57dd41

RaisinTen reviewed May 3, 2022

View reviewed changes

src/stream_base.cc Outdated Show resolved Hide resolved

test/parallel/test-worker-http2-stream-terminate.js Show resolved Hide resolved

RaisinTen mentioned this pull request May 3, 2022

fs: don't end fs promises on Isolate termination #42910

Merged

follow RaisinTen's suggestions

b17b64f

RaisinTen approved these changes May 4, 2022

View reviewed changes

This comment was marked as outdated.

Sign in to view

RaisinTen added the author ready PRs that have at least one approval, no pending requests for changes, and a CI started. label May 4, 2022

addaleax approved these changes May 4, 2022

View reviewed changes

fix node-test-commit-custom-suites-freestyle failure

a7bdb8e

aduh95 approved these changes May 6, 2022

View reviewed changes

aduh95 added commit-queue Add this label to land a pull request using GitHub Actions. commit-queue-squash Add this label to instruct the Commit Queue to squash all the PR commits into the first one. labels May 6, 2022

nodejs-github-bot removed the commit-queue Add this label to land a pull request using GitHub Actions. label May 6, 2022

nodejs-github-bot merged commit 0fc1cf4 into nodejs:master May 6, 2022

RafaelGSS mentioned this pull request May 10, 2022

v18.2.0 proposal #43036

Merged

This was referenced May 12, 2022

CI Reliability 2022-05-12 nodejs/reliability#273

Open

CI Reliability 2022-05-12 nodejs/reliability#275

Closed

CI Reliability 2022-05-13 nodejs/reliability#276

Open

CI Reliability 2022-05-14 nodejs/reliability#277

Open

juanarbol mentioned this pull request May 31, 2022

2022-05-XX, Version 16.16.0 'Gallium' (LTS) #43268

Closed

airtable-keyhanvakil mentioned this pull request Jun 4, 2022

FATAL ERROR: v8::FromJust Maybe value is Nothing #43304

Open

dapplion mentioned this pull request Jun 29, 2022

FATAL ERROR: v8::FromJust Maybe value is Nothing. ChainSafe/lodestar#4145

Closed

ashishchandr70 mentioned this pull request Jul 6, 2022

FATAL ERROR: v8::FromJust Maybe value is Nothing. andywer/threads.js#436

Closed

targos mentioned this pull request Aug 3, 2022

v16.17.0 release proposal #44098

Merged

This was referenced Aug 5, 2022

feat: use child_process for --no-threads vitest-dev/vitest#1790

Closed

Node Error FATAL ERROR: v8::FromJust Maybe value is Nothing, on Windows (local) and CI build (Linux) vitest-dev/vitest#1191

Closed

tony19 mentioned this pull request Aug 9, 2022

Check failed: result.second #43617

Closed

edwardstumpf mentioned this pull request Aug 16, 2022

Running tests crashes node w/ JSDOM and vue 2 vite plugin vitest-dev/vitest#1171

Closed

6 tasks

tony19 mentioned this pull request Aug 17, 2022

ci: retry flaky tests vitejs/vite#9508

Closed

9 tasks

Cherry mentioned this pull request Oct 23, 2023

bump min node version to 16.18 to improve tests flakiness cloudflare/workers-sdk#4266

Merged

2 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

worker: fix stream & termination race bug #42874

worker: fix stream & termination race bug #42874

airtable-keyhanvakil commented Apr 26, 2022 •

edited

Loading

airtable-keyhanvakil commented Apr 26, 2022

RaisinTen left a comment

airtable-keyhanvakil commented Apr 26, 2022

airtable-keyhanvakil commented Apr 28, 2022

RaisinTen commented Apr 30, 2022

airtable-keyhanvakil commented May 2, 2022

RaisinTen left a comment

airtable-keyhanvakil commented May 3, 2022

RaisinTen left a comment

This comment was marked as outdated.

RaisinTen commented May 4, 2022

nodejs-github-bot commented May 4, 2022

airtable-keyhanvakil commented May 5, 2022

nodejs-github-bot commented May 5, 2022

RaisinTen commented May 5, 2022

richardlau commented May 5, 2022

airtable-keyhanvakil commented May 5, 2022 •

edited

Loading

nodejs-github-bot commented May 6, 2022

nodejs-github-bot commented May 6, 2022

nodejs-github-bot commented May 6, 2022

airtable-keyhanvakil commented Jul 6, 2022

aduh95 commented Jul 6, 2022

worker: fix stream & termination race bug #42874

worker: fix stream & termination race bug #42874

Conversation

airtable-keyhanvakil commented Apr 26, 2022 • edited Loading

airtable-keyhanvakil commented Apr 26, 2022

RaisinTen left a comment

Choose a reason for hiding this comment

airtable-keyhanvakil commented Apr 26, 2022

airtable-keyhanvakil commented Apr 28, 2022

RaisinTen commented Apr 30, 2022

airtable-keyhanvakil commented May 2, 2022

RaisinTen left a comment

Choose a reason for hiding this comment

airtable-keyhanvakil commented May 3, 2022

RaisinTen left a comment

Choose a reason for hiding this comment

This comment was marked as outdated.

RaisinTen commented May 4, 2022

nodejs-github-bot commented May 4, 2022

airtable-keyhanvakil commented May 5, 2022

nodejs-github-bot commented May 5, 2022

RaisinTen commented May 5, 2022

richardlau commented May 5, 2022

airtable-keyhanvakil commented May 5, 2022 • edited Loading

nodejs-github-bot commented May 6, 2022

nodejs-github-bot commented May 6, 2022

nodejs-github-bot commented May 6, 2022

airtable-keyhanvakil commented Jul 6, 2022

aduh95 commented Jul 6, 2022

airtable-keyhanvakil commented Apr 26, 2022 •

edited

Loading

airtable-keyhanvakil commented May 5, 2022 •

edited

Loading