Closed gabrielschulhof closed 4 years ago
I will try to reduce the C code needed for reproduction. In particular, the napi_create_ref
/napi_delete_ref
is being performed by node-addon-api for napi_value
s created with napi_create_error
. For each code reduction I will re-test the commitids tested above.
This being N-API I did not recompile the addon for each commit.
@gabrielschulhof totally off topic, what is that bisect ui from?
@devsnek created by hand using text editor π
@devsnek I started with
git log --oneline HEAD~1...master | sed 's/^/[ ][ ] ' >> ~/async_hook.corruption.txt
@gabrielschulhof very nice :clap:
@devsnek then
git log --oneline cb8898c48f~...de877c5781 | wc -l
git log --oneline 74ca960aac~1...99f0404646 | head -n 174 | tail -n 1
# Where 174 is one half of what `wc -l` gave you
Check that out, run the test, fill the checkboxes.
That was just an example. Obviously the commitid range for the two commands has to be the same π
OK, it may not have been https://github.com/nodejs/node/pull/32933. Bisect goes on.
s) Dies sometimes
x) Node.js fails to build
β) Works as expected
1) Dies with above error when running with --expose-gc
2) Dies with above error when running without --expose-gc
,--- running with --expose-gc
/ ,--- running without --expose-gc
/ /
/ [s][s] 99f0404646 doc: specify encoding in text/html examples
| ... (172 commits)
| [β][s] a2b1b92e30 test: AsyncLocalStorage works with thenables
| ... (40 commits)
| [s][s] 8ef86a920c quic: fix clang warning
| ... (40 commits)
| [1][2] d7d79f2163 quic: avoid memory fragmentation issue
| ... (91 commits)
| [1][2] 74ca960aac lib: initial experimental AbortController implementation
| [β][2] 3e2a300710 src: use ToLocal in SafeGetenv
| ... (24 commits)
| [β][2] b1704e4347 meta: fix a typo in the flaky test template
| ... (24 commits)
| [β][2] e3b54b4d1c wasi: allow WASI stdio to be configured
| ... (4 commits)
| [β][2] cd9bc20cb4 doc: add --experimental-top-level-await to man page
| [β][2] 4bdab881b8 console: name console functions appropriately
| [1][2] 87629d7e7c console: mark special console properties as non-enumerable
| [1][2] b61249e32d console: remove dead code
| ... (2 commits)
| [1][2] 54e5c36e73 build: fix GetCurrentThreadStackLimits error on Windows on Arm
| ... (17 commits)
| [1][2] 54b36e401d fs: reimplement read and write streams using stream.construct
unstable| ... (20 commits)
| [1][2] 6443ab9595 module: deprecate module.parent
| ... (126 commits)
| [1][2] 5bb4d01fbe doc: add note about clientError writable handling
| --- begin 32831
| [ ][ ] 0ddae48b88 test: stop testing --interpreted-frames-native-stack for s390x
| [ ][ ] aa01fcae49 test: fix test-zlib-unused-weak on V8 8.2
| [1][2] d1156d0d2f test: rename FinalizationGroup to FinalizationRegistry
| [1][2] f945c54aa6 deps: V8: cherry-pick 74d50c5063b3
| [ ][ ] ae7e45c031 deps: V8: cherry-pick e29c62b74854
| [ ][ ] 7baaab014b deps: V8: cherry-pick 3f8dc4b2e5ba
| [ ][ ] 56bdec44a8 deps: V8: cherry-pick e1eac1b16c96
| [ ][ ] 0d50ba5d48 deps: fix V8 8.3 on SmartOS
| [x][x] 54ae041309 deps: patch V8 to run on Xcode 8
| [x][x] e9a6ba0a4c deps: V8: silence irrelevant warnings
| [x][x] 32be677f49 deps: make v8.h compatible with VS2015
| [x][x] 9dfaf49b84 deps: V8: forward declaration of `Rtl*FunctionTable`
| [ ][ ] 55f7ae6386 deps: V8: patch register-arm64.h
| [ ][ ] 6b5ea2efa2 deps: patch V8 to run on older XCode versions
| [ ][ ] c3866a1b3e deps: V8: un-cherry-pick bd019bd
| [ ][ ] a48928836a deps: update V8 dtrace & postmortem metadata
| [ ][ ] db0ed118d8 tools: update V8 gypfiles for V8 8.3
| [x][x] 308900faef src: update NODE_MODULE_VERSION to 84
| [ ][ ] 37abad4340 build: reset embedder string to "-node.0"
\ [x][x] 1d6adf7432 deps: update V8 to 8.3.110.9
/ [β][β] aee36a0447 src: delete unused variables to resolve compile time print warning
| --- end 32831
| [β][β] cfec30fef3 deps: update to ICU 67.1
| ... (20 commits)
| [β][β] 1aa491a88f http2: add `bytesWritten` test for `Http2Stream`
| ... (42 commits)
| [β][β] c81e5f699e doc: mark assert.CallTracker experimental
| ... (85 commits)
| [β][β] c15a27cab3 stream: don't wait for close on legacy streams
| [β][β] f5c11a1a0a stream: don't emit finish after close
| [β][β] 9f14584f2a deps: update archs files for OpenSSL-1.1.1g
| [ ][ ] 5509c6355c deps: upgrade openssl sources to 1.1.1g
| [β][β] 58682d823a tls: add highWaterMark option for connect
stable| ... (3 commits)
| [β][β] 53b8133656 doc: avoid tautology in README
| ... (9 commits)
| [β][β] 654c0ace7b src: fix compiler warnings in node_http2.cc
| ... (18 commits)
| [β][β] 01e158c600 doc: remove repeated word in modules.md
| ... (36 commits)
| [β][β] e231e1a0d8 src: elevate v8 namespaces
| ... (74 commits)
| [β][β] 203776fb71 build: fix LINT_MD_NEWER assignment
| ... (149 commits)
| [β][β] 8ec533d890 benchmark: use let instead of var in tls
| ... (299 commits)
\ [β][β] 67d45fb298 2020-03-04 Version 13.10.1 (Current)
Looks like moving to V8 8.3.110.9 introduced the instability (in #32831).
The problem also exists if we remove napi_create_reference/napi_delete_reference
:
#include <stdio.h>
#include <assert.h>
#include <node_api.h>
static void delete_me(napi_env env, void* data, void* hint) {
napi_status status;
napi_value string;
napi_value error;
fprintf(stderr, "delete_me\n");
status = napi_create_string_utf8(env,
"Finalizer exception",
NAPI_AUTO_LENGTH,
&string);
assert(status == napi_ok);
status = napi_create_error(env, NULL, string, &error);
assert(status == napi_ok);
status = napi_throw(env, error);
assert(status == napi_ok);
}
static napi_value CreateException(napi_env env, napi_callback_info info) {
napi_value ret;
napi_status status = napi_create_external(env, NULL, delete_me, NULL, &ret);
assert(status == napi_ok);
return ret;
}
NAPI_MODULE_INIT() {
napi_value result;
napi_status status = napi_create_function(env,
"createException",
NAPI_AUTO_LENGTH,
CreateException,
NULL,
&result);
assert(status == napi_ok);
return result;
}
The code can be reduced to
#include <stdio.h>
#include <assert.h>
#include <node_api.h>
static void delete_me(napi_env env, void* data, void* hint) {
fprintf(stderr, "delete_me\n");
napi_status status = napi_throw_error(env, NULL, "Finalizer exception");
assert(status == napi_ok);
}
static napi_value CreateException(napi_env env, napi_callback_info info) {
napi_value ret;
napi_status status = napi_create_external(env, NULL, delete_me, NULL, &ret);
assert(status == napi_ok);
return ret;
}
NAPI_MODULE_INIT() {
napi_value result;
napi_status status = napi_create_function(env,
"createException",
NAPI_AUTO_LENGTH,
CreateException,
NULL,
&result);
assert(status == napi_ok);
return result;
}
I set a hardware watchpoint at the location from which async_id_fields_.GetValue(kExecutionAsyncId)
retrieves the value, and it is being set to 2 by the following stack:
0x00000000016d7317 in v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::TypedElementsAccessor<(v8::internal::ElementsKind)24, double>, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)24> >::Set (this=<optimized out>, holder=..., entry=..., value=...) at ../deps/v8/src/objects/elements.cc:3002
3002 static void SetImpl(ElementType* data_ptr, size_t entry, ElementType value) {
#0 0x00000000016d7317 in v8::internal::(anonymous namespace)::ElementsAccessorBase<v8::internal::(anonymous namespace)::TypedElementsAccessor<(v8::internal::ElementsKind)24, double>, v8::internal::(anonymous namespace)::ElementsKindTraits<(v8::internal::ElementsKind)24> >::Set (this=<optimized out>, holder=..., entry=..., value=...) at ../deps/v8/src/objects/elements.cc:3002
#1 0x00000000017f3d34 in v8::internal::LookupIterator::WriteDataValue (this=this@entry=0x7fffffffd130, value=value@entry=..., initializing_store=initializing_store@entry=false) at ../deps/v8/src/objects/objects.h:607
#2 0x000000000182eceb in v8::internal::Object::SetDataProperty (it=it@entry=0x7fffffffd130, value=value@entry=...) at ../deps/v8/src/objects/objects.cc:2760
#3 0x00000000018520d7 in v8::internal::Object::SetPropertyInternal (it=it@entry=0x7fffffffd130, value=..., should_throw=..., store_origin=store_origin@entry=v8::internal::StoreOrigin::kMaybeKeyed, found=found@entry=0x7fffffffd0c8) at ../deps/v8/src/objects/objects.cc:2546
#4 0x00000000018527f9 in v8::internal::Object::SetProperty (it=it@entry=0x7fffffffd130, value=value@entry=..., store_origin=store_origin@entry=v8::internal::StoreOrigin::kMaybeKeyed, should_throw=should_throw@entry=...) at ../deps/v8/src/objects/objects.cc:2565
#5 0x0000000001a28c3d in v8::internal::Runtime::SetObjectProperty (isolate=isolate@entry=0x5807010, object=object@entry=..., key=key@entry=..., value=..., store_origin=store_origin@entry=v8::internal::StoreOrigin::kMaybeKeyed, should_throw=..., should_throw@entry=...) at ../deps/v8/src/runtime/runtime-object.cc:427
#6 0x0000000001a366e4 in v8::internal::__RT_impl_Runtime_SetKeyedProperty (args=..., isolate=isolate@entry=0x5807010) at ../deps/v8/include/v8.h:9970
#7 0x0000000001a36a7a in v8::internal::Runtime_SetKeyedProperty (args_length=3, args_object=0x7fffffffd290, isolate=0x5807010) at ../deps/v8/src/runtime/runtime-object.cc:673
#8 0x0000000002050e80 in Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit () at ../../deps/v8/../../deps/v8/src/builtins/promise-misc.tq:111
#9 0x0000000002299ee3 in Builtins_StaKeyedPropertyHandler () at ../deps/v8/src/interpreter/interpreter-generator.cc:615
#10 0x00003f35de8765d9 in ?? ()
#11 0x0000000000000000 in ?? ()
@gabrielschulhof You can use call (void) _v8_internal_Print_StackTrace()
to print a JS stack trace, which is going to be a lot more useful there I think :slightly_smiling_face: (generally, the gdb shortcuts in https://github.com/v8/v8/blob/master/tools/gdbinit are super useful)
@addaleax thanks! I'll try to produce a hybrid stack trace next.
@gabrielschulhof That being said β¦ it looks like youβre calling into JS/throwing an exception from the finalizer β that canβt be right? We allow that for Buffer
finalizers but go out of our way (via SetImmediate()
) to make that possible there, but not for other finalizers. If you allow running JS/throwing exceptions from regular finalizers, thatβs bound to be problematic because GC can run during any other code, including without a JS stack at all.
@addaleax hmmm ... finalizers are supposed to be able to execute JS. Their signature accepts a napi_env
. If that's no longer true, we need to make some drastic changes.
@addaleax the original motivation was to make node-addon-api callbacks more consistent. In those headers we don't have CallIntoModule
like we have in core, but we need it, because of the way we convert C++ exceptions that are really napi_value
s containing JS errors to be thrown on the JS side into JS exceptions. Any calls made into user code need to expect a C++ exception, including calling the user's finalizer.
@addaleax hmmm ... finalizers are supposed to be able to execute JS.
@gabrielschulhof In that case, I would delay their execution with SetImmediate()
like we do for Buffer
s.
https://github.com/nodejs/node/pull/32933 seems to have introduced the following error:
The error is produced by building the following add-on:
Tested with and without
--expose-gc
:Expected output for with
--expose-gc
β none Expected output for without--expose-gc
(repeated 20 times):The latter is expected because the thrown error is about
global.gc()
missing fromglobal
not about the error thrown from the native code, so itsanException.message
will not match the regex.A git bisect performed manually reveals that https://github.com/nodejs/node/pull/32933 seems to have introduced some instability in the correct functioning of the above add-on:
Tested on my laptop (Fedora 30 x64).