node-api/test_exception fails in debug mode

[addaleax]

• 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

[mhdawson]

@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]

@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]

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]

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

[mhdawson]

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]

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]

ping @nodejs/n-api

[gabrielschulhof]

@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]

@addaleax can we close this?

[addaleax]

@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.