Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

node-api/test_exception fails in debug mode #26754

Closed
addaleax opened this issue Mar 18, 2019 · 10 comments
Closed

node-api/test_exception fails in debug mode #26754

addaleax opened this issue Mar 18, 2019 · 10 comments
Assignees
Labels
build Issues and PRs related to build files or the CI. confirmed-bug Issues with confirmed bugs. node-api Issues and PRs related to the Node-API. test Issues and PRs related to the tests.

Comments

@addaleax
Copy link
Member

addaleax commented Mar 18, 2019

  • Version: master
  • Platform: Linux (presumably any)
  • Subsystem: n-api
Starting program: node_g --expose-gc test/node-api/test_exception/test.js
[...]
#
# Fatal error in ../deps/v8/src/heap/heap-inl.h, line 164
# Debug check failed: AllowHeapAllocation::IsAllowed().
#
#
#
#FailureMessage Object: 0x7fffeb649850
Thread 1 "node_g" received signal SIGILL, Illegal instruction.
v8::base::OS::Abort () at ../deps/v8/src/base/platform/platform-posix.cc:400
400	    V8_IMMEDIATE_CRASH();
(gdb) bt
#0  v8::base::OS::Abort () at ../deps/v8/src/base/platform/platform-posix.cc:400
#1  0x000055592c258a2b in V8_Fatal (file=0x55592cb79048 "../deps/v8/src/heap/heap-inl.h", line=164, format=format@entry=0x55592cf8704a "Debug check failed: %s.") at ../deps/v8/src/base/logging.cc:171
#2  0x000055592c258a45 in v8::base::(anonymous namespace)::DefaultDcheckHandler (file=<optimized out>, line=<optimized out>, message=<optimized out>) at ../deps/v8/src/base/logging.cc:56
#3  0x000055592b69d1a8 in v8::internal::Heap::AllocateRaw (this=0x55592df7a780, size_in_bytes=24, space=v8::internal::NEW_SPACE, alignment=v8::internal::kWordAligned) at ../deps/v8/src/heap/heap-inl.h:164
#4  0x000055592b6e031f in v8::internal::Heap::AllocateRawWithLightRetry (this=this@entry=0x55592df7a780, size=size@entry=24, space=space@entry=v8::internal::NEW_SPACE, alignment=alignment@entry=v8::internal::kWordAligned) at ../deps/v8/src/heap/heap.cc:4326
#5  0x000055592b6e042e in v8::internal::Heap::AllocateRawWithRetryOrFail (this=this@entry=0x55592df7a780, size=24, space=space@entry=v8::internal::NEW_SPACE, alignment=alignment@entry=v8::internal::kWordAligned) at ../deps/v8/src/heap/heap.cc:4347
#6  0x000055592b68e9e4 in v8::internal::Factory::AllocateRawWithAllocationSite (this=this@entry=0x55592df71960, map=map@entry=..., pretenure=pretenure@entry=v8::internal::NOT_TENURED, allocation_site=...) at ../deps/v8/src/heap/factory.cc:143
#7  0x000055592b6a43b8 in v8::internal::Factory::NewJSObjectFromMap (this=this@entry=0x55592df71960, map=..., map@entry=..., pretenure=pretenure@entry=v8::internal::NOT_TENURED, allocation_site=..., allocation_site@entry=...) at ../deps/v8/src/heap/factory.cc:3059
#8  0x000055592b8f5729 in v8::internal::JSObject::New (constructor=constructor@entry=..., new_target=..., site=site@entry=...) at ../deps/v8/src/objects.cc:1379
#9  0x000055592b840d2f in v8::internal::ErrorUtils::Construct (isolate=isolate@entry=0x55592df71960, target=..., new_target=..., message=..., mode=mode@entry=v8::internal::SKIP_NONE, caller=..., caller@entry=..., suppress_detailed_trace=false) at ../deps/v8/src/messages.cc:1160
#10 0x000055592b68d971 in v8::internal::Factory::NewError (this=this@entry=0x55592df71960, constructor=..., message=..., message@entry=...) at ../deps/v8/src/heap/factory.cc:2379
#11 0x000055592b1020ba in v8::Exception::Error (raw_message=...) at ../deps/v8/src/api.cc:8988
#12 0x000055592adde733 in napi_throw_error (env=0x55592e09ac40, code=0x0, msg=0x7fdfd2dfcb55 "Error during Finalize") at ../src/js_native_api_v8.cc:1803
#13 0x00007fdfd2dfc8d5 in finalizer (env=0x55592e09ac40, data=0x7fdfd2ffd0d0 <buffer_data>, hint=0x0) at ../test_exception.c:5
#14 0x000055592adfe1f3 in v8impl::(anonymous namespace)::BufferFinalizer::<lambda()>::operator()(void) const (__closure=0x7fffeb64a030) at ../src/node_api.cc:40
#15 0x000055592ae0252a in NapiCallIntoModule<v8impl::(anonymous namespace)::BufferFinalizer::FinalizeBufferCallback(char*, void*)::<lambda()>&, NapiCallIntoModuleThrow(napi_env, T&&) [with T = v8impl::(anonymous namespace)::BufferFinalizer::FinalizeBufferCallback(char*, void*)::<lambda()>]::<lambda(v8::Local<v8::Value>)> >(napi_env, v8impl::(anonymous namespace)::BufferFinalizer::<lambda()> &, <lambda(v8::Local<v8::Value>)> &&) (env=0x55592e09ac40, call=..., handle_exception=...) at ../src/js_native_api_v8.h:121
#16 0x000055592ae01e36 in NapiCallIntoModuleThrow<v8impl::(anonymous namespace)::BufferFinalizer::FinalizeBufferCallback(char*, void*)::<lambda()> >(napi_env, v8impl::(anonymous namespace)::BufferFinalizer::<lambda()> &&) (env=0x55592e09ac40, call=...) at ../src/js_native_api_v8.h:132
#17 0x000055592adfe250 in v8impl::(anonymous namespace)::BufferFinalizer::FinalizeBufferCallback (data=0x7fdfd2ffd0d0 <buffer_data> "", hint=0x55592e0825b0) at ../src/node_api.cc:39
#18 0x000055592ae0985a in node::Buffer::(anonymous namespace)::CallbackInfo::WeakCallback (this=0x55592e0bbb50, isolate=0x55592df71960) at ../src/node_buffer.cc:151
#19 0x000055592ae09803 in node::Buffer::(anonymous namespace)::CallbackInfo::WeakCallback (data=...) at ../src/node_buffer.cc:145
#20 0x000055592b66c7ec in v8::internal::GlobalHandles::PendingPhantomCallback::Invoke (this=this@entry=0x7fffeb64a120, isolate=0x55592df71960) at ../deps/v8/src/global-handles.cc:915
#21 0x000055592b66f986 in v8::internal::GlobalHandles::InvokeFirstPassWeakCallbacks (this=0x55592df96b50) at ../deps/v8/src/global-handles.cc:877
#22 0x000055592b6dc64c in v8::internal::Heap::PerformGarbageCollection (this=this@entry=0x55592df7a780, collector=collector@entry=v8::internal::MARK_COMPACTOR, gc_callback_flags=gc_callback_flags@entry=v8::kGCCallbackFlagForced) at ../deps/v8/src/heap/heap.cc:1739
#23 0x000055592b6dd384 in v8::internal::Heap::CollectGarbage (this=this@entry=0x55592df7a780, space=space@entry=v8::internal::OLD_SPACE, gc_reason=<optimized out>, gc_callback_flags=v8::kGCCallbackFlagForced) at ../deps/v8/src/heap/heap.cc:1327
#24 0x000055592b6dd764 in v8::internal::Heap::CollectAllGarbage (this=0x55592df7a780, flags=<optimized out>, gc_reason=<optimized out>, gc_callback_flags=<optimized out>) at ../deps/v8/src/heap/heap.cc:1070
#25 0x000055592b1cc261 in v8::internal::FunctionCallbackArguments::Call (this=this@entry=0x7fffeb64a500, handler=..., handler@entry=...) at ../deps/v8/src/api-arguments-inl.h:146
#26 0x000055592b1cee18 in v8::internal::(anonymous namespace)::HandleApiCallHelper<false> (isolate=isolate@entry=0x55592df71960, function=..., function@entry=..., new_target=..., new_target@entry=..., fun_data=..., receiver=..., receiver@entry=..., args=...) at ../deps/v8/src/builtins/builtins-api.cc:109
#27 0x000055592b1d0319 in v8::internal::Builtin_Impl_HandleApiCall (args=..., isolate=isolate@entry=0x55592df71960) at ../deps/v8/src/builtins/builtins-api.cc:139
#28 0x000055592b1d0bdd in v8::internal::Builtin_HandleApiCall (args_length=5, args_object=0x7fffeb64a740, isolate=0x55592df71960) at ../deps/v8/src/builtins/builtins-api.cc:127
#29 0x000055592c669592 in Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit () at ../deps/v8/src/code-stub-assembler.cc:128
#30 0x000055592c3753c8 in Builtins_InterpreterEntryTrampoline () at ../deps/v8/src/builtins/builtins-collections-gen.cc:1308
[...]

Three questions:

  • Should we keep this test? At the moment seems to test something invalid, namely throwing an error during GC.
  • Alternatively, should we try to switch over to a second pass callback here as well, like we did in n-api: finalize during second-pass callback #25992, but for all Buffers?
  • Why doesn’t this fail in CI? Looking at CI output, we don’t seem to test addons in debug mode at all? That seems pretty bad, they are one of the test suites that need it the most.

/cc @nodejs/n-api @nodejs/build

@addaleax addaleax added node-api Issues and PRs related to the Node-API. build Issues and PRs related to build files or the CI. test Issues and PRs related to the tests. labels Mar 18, 2019
@mhdawson
Copy link
Member

@addaleax for context is that any addons or just n-api addons? I'm guessing we don't test either in debug but thought I should ask to be sure.

@addaleax
Copy link
Member Author

@mhdawson It doesn’t look like any add-ons are tested, but somebody from the build WG should be able to tell your for sure.

@mhdawson
Copy link
Member

In terms of add-on testing if it's not in the main test job then I think the answer is no. We do have another job that tests node-addon-api but that does not include debug either.

@addaleax
Copy link
Member Author

@mhdawson Does that mean that addons aren’t tested on all platforms in general, not just not on debug builds?

@mhdawson
Copy link
Member

There are addon tests which run in the main test job for all platforms but that runs on regular not debug builds. So we have addon testing but I think in release not debug mode.

@mhdawson
Copy link
Member

As an example in:https://ci.nodejs.org/job/node-test-commit-linux/nodes=centos7-64-gcc6/26253/consoleFull

these are some of the napi addon tests running:

13:53:27 ok 2344 js-native-api/test_array/test
13:53:27   ---
13:53:27   duration_ms: 0.173
13:53:27   ...
13:53:28 ok 2345 js-native-api/test_new_target/test
13:53:28   ---
13:53:28   duration_ms: 0.182
13:53:28   ...
13:53:28 ok 2346 js-native-api/test_exception/test
13:53:28   ---
13:53:28   duration_ms: 0.179
13:53:28   ...
13:53:28 ok 2347 js-native-api/test_function/test
13:53:28   ---
13:53:28   duration_ms: 0.182
13:53:28   ...
13:53:28 ok 2348 js-native-api/4_object_factory/test
13:53:28   ---

@addaleax
Copy link
Member Author

ping @nodejs/n-api

@gabrielschulhof gabrielschulhof self-assigned this May 13, 2019
@gabrielschulhof
Copy link
Contributor

@addaleax I tested with 6be5c3b by performing the following steps:

git clean -x -d -f -f && \
  ./configure --debug && \
  nice -n 19 make -j6 && \
  nice -n 19 make build-js-native-api-tests && \
  ./node_g --expose-gc test/js-native-api/test_exception/test.js

I was unable to reproduce the error.

@gabrielschulhof
Copy link
Contributor

@addaleax can we close this?

@gabrielschulhof gabrielschulhof removed their assignment Jun 4, 2019
@addaleax
Copy link
Member Author

addaleax commented Jun 5, 2019

@gabrielschulhof No, I don’t think anything here has been addressed? This still crashes for me, and I don’t think the CI testing situation has been fixed either.

Either way, the cause of the bug is already determined, so the question still isn’t whether we have to do anything here (we do), but whether we want to modify the behaviour here (e.g. use a SecondPassCallback) or declare this test to be doing something invalid, and then fix CI.

./node_g --expose-gc test/js-native-api/test_exception/test.js

This should be ./node_g --expose-gc test/node-api/test_exception/test.js.

@addaleax addaleax added the confirmed-bug Issues with confirmed bugs. label Jun 5, 2019
@addaleax addaleax self-assigned this Jun 5, 2019
addaleax added a commit to addaleax/node that referenced this issue Jun 5, 2019
We have a test that verifies that JS execution from the Buffer
finalizer is accepted, and that errors thrown are passed
down synchronously.

However, since the finalizer executes during GC, this is behaviour is
fundamentally invalid and, for good reasons, disallowed by the
JS engine. This leaves us with the options of either finding a way
to allow JS execution from the callback, or explicitly forbidding it on
the N-API side as well.

This commit implements the former option, since it is the more
backwards-compatible one, in the sense that the current situation
sometimes appears to work as well and we should not break that
behaviour if we don’t have to, but rather try to actually make it
work reliably.

Since GC timing is largely unobservable anyway, this commit moves
the callback into a `SetImmediate()`, as we do elsewhere in the code,
and a second pass callback is not an easily implemented option,
as the API is supposed to wrap around Node’s `Buffer` API.
In this case, exceptions are handled like other uncaught exceptions.

Two tests have to be adjusted to account for the timing difference.
This is unfortunate, but unavoidable if we want to conform to the
JS engine API contract and keep all tests.

Fixes: nodejs#26754
addaleax added a commit that referenced this issue Jun 14, 2019
We have a test that verifies that JS execution from the Buffer
finalizer is accepted, and that errors thrown are passed
down synchronously.

However, since the finalizer executes during GC, this is behaviour is
fundamentally invalid and, for good reasons, disallowed by the
JS engine. This leaves us with the options of either finding a way
to allow JS execution from the callback, or explicitly forbidding it on
the N-API side as well.

This commit implements the former option, since it is the more
backwards-compatible one, in the sense that the current situation
sometimes appears to work as well and we should not break that
behaviour if we don’t have to, but rather try to actually make it
work reliably.

Since GC timing is largely unobservable anyway, this commit moves
the callback into a `SetImmediate()`, as we do elsewhere in the code,
and a second pass callback is not an easily implemented option,
as the API is supposed to wrap around Node’s `Buffer` API.
In this case, exceptions are handled like other uncaught exceptions.

Two tests have to be adjusted to account for the timing difference.
This is unfortunate, but unavoidable if we want to conform to the
JS engine API contract and keep all tests.

Fixes: #26754

PR-URL: #28082
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
Reviewed-By: Gabriel Schulhof <gabriel.schulhof@intel.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
BridgeAR pushed a commit that referenced this issue Jun 17, 2019
Previously, the throwing callback would have been re-executed in case
of an exception. This patch corrects the calculation to exclude the
callback.

PR-URL: #28082
Fixes: #26754
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
Reviewed-By: Gabriel Schulhof <gabriel.schulhof@intel.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
BridgeAR pushed a commit that referenced this issue Jun 17, 2019
We have a test that verifies that JS execution from the Buffer
finalizer is accepted, and that errors thrown are passed
down synchronously.

However, since the finalizer executes during GC, this is behaviour is
fundamentally invalid and, for good reasons, disallowed by the
JS engine. This leaves us with the options of either finding a way
to allow JS execution from the callback, or explicitly forbidding it on
the N-API side as well.

This commit implements the former option, since it is the more
backwards-compatible one, in the sense that the current situation
sometimes appears to work as well and we should not break that
behaviour if we don’t have to, but rather try to actually make it
work reliably.

Since GC timing is largely unobservable anyway, this commit moves
the callback into a `SetImmediate()`, as we do elsewhere in the code,
and a second pass callback is not an easily implemented option,
as the API is supposed to wrap around Node’s `Buffer` API.
In this case, exceptions are handled like other uncaught exceptions.

Two tests have to be adjusted to account for the timing difference.
This is unfortunate, but unavoidable if we want to conform to the
JS engine API contract and keep all tests.

Fixes: #26754

PR-URL: #28082
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
Reviewed-By: Gabriel Schulhof <gabriel.schulhof@intel.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
targos pushed a commit that referenced this issue Jun 18, 2019
Previously, the throwing callback would have been re-executed in case
of an exception. This patch corrects the calculation to exclude the
callback.

PR-URL: #28082
Fixes: #26754
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
Reviewed-By: Gabriel Schulhof <gabriel.schulhof@intel.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
targos pushed a commit that referenced this issue Jun 18, 2019
We have a test that verifies that JS execution from the Buffer
finalizer is accepted, and that errors thrown are passed
down synchronously.

However, since the finalizer executes during GC, this is behaviour is
fundamentally invalid and, for good reasons, disallowed by the
JS engine. This leaves us with the options of either finding a way
to allow JS execution from the callback, or explicitly forbidding it on
the N-API side as well.

This commit implements the former option, since it is the more
backwards-compatible one, in the sense that the current situation
sometimes appears to work as well and we should not break that
behaviour if we don’t have to, but rather try to actually make it
work reliably.

Since GC timing is largely unobservable anyway, this commit moves
the callback into a `SetImmediate()`, as we do elsewhere in the code,
and a second pass callback is not an easily implemented option,
as the API is supposed to wrap around Node’s `Buffer` API.
In this case, exceptions are handled like other uncaught exceptions.

Two tests have to be adjusted to account for the timing difference.
This is unfortunate, but unavoidable if we want to conform to the
JS engine API contract and keep all tests.

Fixes: #26754

PR-URL: #28082
Reviewed-By: Michael Dawson <michael_dawson@ca.ibm.com>
Reviewed-By: Gabriel Schulhof <gabriel.schulhof@intel.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
build Issues and PRs related to build files or the CI. confirmed-bug Issues with confirmed bugs. node-api Issues and PRs related to the Node-API. test Issues and PRs related to the tests.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants