Node: flaky: sequential/test-cli-syntax-*

Created on 16 Nov 2018  Â·  31Comments  Â·  Source: nodejs/node
  • Version: master
  • Platform: Windows 2008R2
  • Subsystem: cli

  • test file - parallel/test-cli-syntax
  • CI job binary-windows/21615/COMPILED_BY=vs2017,RUNNER=win2008r2
  • CI worker test-rackspace-win2008r2-x64-5
  • output:
    11:40:44 not ok 71 parallel/test-cli-syntax 11:40:44 --- 11:40:44 duration_ms: 1.229 11:40:44 severity: fail 11:40:44 exitcode: 1 11:40:44 stack: |- 11:40:44 assert.js:86 11:40:44 throw new AssertionError(obj); 11:40:44 ^ 11:40:44 11:40:44 AssertionError [ERR_ASSERTION]: Expected values to be strictly equal: 11:40:44 + actual - expected 11:40:44 11:40:44 + 3221225477 11:40:44 - 1 11:40:44 at common.mustCall (c:\workspace\node-test-binary-windows\test\parallel\test-cli-syntax.js:59:14) 11:40:44 at c:\workspace\node-test-binary-windows\test\common\index.js:346:15 11:40:44 at ChildProcess.exithandler (child_process.js:301:5) 11:40:44 at ChildProcess.emit (events.js:182:13) 11:40:44 at maybeClose (internal/child_process.js:977:16) 11:40:44 at Socket.stream.socket.on (internal/child_process.js:395:11) 11:40:44 at Socket.emit (events.js:182:13) 11:40:44 at Pipe._handle.close (net.js:608:12) 11:40:44 ...\
CI / flaky test cli test
Source
picture refack

All 31 comments

Also failed on linux here: https://ci.nodejs.org/job/node-test-commit-linux-containered/8755/nodes=ubuntu1604_sharedlibs_openssl110_x64/consoleFull

21:14:55 not ok 192 parallel/test-cli-syntax
21:14:55   ---
21:14:55   duration_ms: 2.556
21:14:55   severity: fail
21:14:55   exitcode: 1
21:14:55   stack: |-
21:14:55     assert.js:753
21:14:55         throw newErr;
21:14:55         ^
21:14:55     
21:14:55     AssertionError [ERR_ASSERTION]: ifError got unwanted exception: Command failed: /home/iojs/build/workspace/node-test-commit-linux-containered/out/Release/node --check /home/iojs/build/workspace/node-test-commit-linux-containered/test/fixtures/syntax/illegal_if_not_wrapped.js
21:14:55     Segmentation fault (core dumped)
21:14:55     
21:14:55         at ChildProcess.exithandler (child_process.js:294:12)
21:14:55         at ChildProcess.emit (events.js:189:13)
21:14:55         at maybeClose (internal/child_process.js:977:16)
21:14:55         at Socket.stream.socket.on (internal/child_process.js:395:11)
21:14:55         at Socket.emit (events.js:189:13)
21:14:55         at Pipe._handle.close (net.js:608:12)
21:14:55   ...

Worker: https://ci.nodejs.org/computer/test-joyent-ubuntu1604_sharedlibs_container-x64-4/
Config: ubuntu1604_sharedlibs_openssl110_x64

mhdawson picture mhdawson on 20 Nov 2018

@mhdawson Core dumped? Yikes! Hopefully build-related and not related to the test? @nodejs/build

Trott picture Trott on 23 Nov 2018

Core dumped? Yikes!

IIUC the core dump was for the tested spawned child process, not the testing process.
https://github.com/nodejs/node/blob/d45e303ac67c027bbad709f465e479ac789302a7/test/parallel/test-cli-syntax.js#L35-L40

refack picture refack on 23 Nov 2018

Managed to get a core dump locally; interesting parts of the thread stack traces:

Thread 7 (Thread 0x7fd3e1708740 (LWP 32401)):
#0  _int_free (have_lock=0, p=0x557d4eedc500, av=0x7fd3e05a3c40 <main_arena>) at malloc.c:4167
#1  __GI___libc_free (mem=0x557d4eedc510) at malloc.c:3124
#2  0x0000557d4d144471 in std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > >::_M_erase(std::_Rb_tree_node<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >*) ()
#3  0x0000557d4d1445e8 in node::native_module::NativeModuleLoader::~NativeModuleLoader() ()
#4  0x00007fd3e01fb041 in __run_exit_handlers (status=0, listp=0x7fd3e05a3718 <__exit_funcs>, run_list_atexit=run_list_atexit@entry=true, run_dtors=run_dtors@entry=true) at exit.c:108
#5  0x00007fd3e01fb13a in __GI_exit (status=<optimized out>) at exit.c:139
#6  0x0000557d4d113131 in node::Environment::Exit(int) ()
#7  0x0000557d4d1388d1 in node::Exit(v8::FunctionCallbackInfo<v8::Value> const&) ()
#8  0x0000557d4d3b1237 in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) ()
#9  0x0000557d4d3b2558 in v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) ()
#10 0x00001c51e784fb5d in ?? ()
#11 0x00001c51e7884b30 in ?? ()
#12 0x00001c51e784fac1 in ?? ()
#13 0x00007ffef03e0990 in ?? ()
#14 0x0000000000000006 in ?? ()

[...]

Thread 1 (Thread 0x7fd3df9b6700 (LWP 32404)):
#0  0x0000557d4ef3a400 in ?? ()
#1  0x0000557d4d6eb6dc in v8::internal::ArrayBufferCollector::FreeingTask::RunInternal() ()
#2  0x0000557d4d1cbc45 in node::(anonymous namespace)::PlatformWorkerThread(void*) ()
#3  0x00007fd3e05b06db in start_thread (arg=0x7fd3df9b6700) at pthread_create.c:463
#4  0x00007fd3e02d988f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

I feel like I’ve been seeing a lot more issues based on race conditions with C++ destructors being run from __run_exit_handlers(), but before all threads are torn down… I’m not sure what would have caused that change. Should we maybe be calling _exit() instead? Is there a way to first stop all other threads?

/cc @joyeecheung

addaleax picture addaleax on 4 Dec 2018

About the specific stack trace, was the destructor being called when one of the strings on the native module loader was already destroyed? I think the std::strings on the loader should all be local to it, so it's kind of difficult to how would the order be reversed..

On the race condition in general, is the current expectation to destroy all the per-process globals only after all the threads are torn down? I wonder if using shared_ptr for these globals would help, but that probably doesn't actually solve the root cause..

joyeecheung picture joyeecheung on 4 Dec 2018

Potential fix is in https://github.com/nodejs/node/pull/24828 :)

addaleax picture addaleax on 4 Dec 2018

And no, I don’t think this is about the specific stack trace – it’s probably some destructor that was called earlier that destroyed some resource on which the V8 platform worker thread relied, or something similar, I would say.

addaleax picture addaleax on 4 Dec 2018

Another failure:

assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

139 !== 1

    at common.mustCall (/home/iojs/build/workspace/node-test-commit-linux-containered/test/parallel/test-cli-syntax.js:97:14)
    at /home/iojs/build/workspace/node-test-commit-linux-containered/test/common/index.js:346:15
    at ChildProcess.exithandler (child_process.js:301:5)
    at ChildProcess.emit (events.js:189:13)
    at maybeClose (internal/child_process.js:977:16)
    at Socket.stream.socket.on (internal/child_process.js:395:11)
    at Socket.emit (events.js:189:13)
    at Pipe._handle.close (net.js:612:12)
Fishrock123 picture Fishrock123 on 4 Dec 2018

another failure

assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:
+ actual - expected

+ 3221225477
- 1
    at common.mustCall (c:\workspace\node-test-binary-windows\test\parallel\test-cli-syntax.js:65:14)
    at c:\workspace\node-test-binary-windows\test\common\index.js:346:15
    at ChildProcess.exithandler (child_process.js:301:5)
    at ChildProcess.emit (events.js:189:13)
    at maybeClose (internal/child_process.js:977:16)
    at Socket.stream.socket.on (internal/child_process.js:395:11)
    at Socket.emit (events.js:189:13)
    at Pipe._handle.close (net.js:612:12)
MylesBorins picture MylesBorins on 5 Dec 2018

Interestingly, this only seems to happen with this specific test, it seems somehow -c triggers the race condition more often than the others, see https://github.com/nodejs/reliability/issues/19

joyeecheung picture joyeecheung on 5 Dec 2018

This is happening so often that I guess there's not much to be gained in pointing out when it happens much anymore, but here's one anyway:

https://ci.nodejs.org/job/node-test-commit-aix/19414/nodes=aix61-ppc64/consoleText

not ok 286 parallel/test-cli-syntax
  ---
  duration_ms: 24.538
  severity: fail
  exitcode: 1
  stack: |-
    assert.js:86
      throw new AssertionError(obj);
      ^

    AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

    null !== 1

        at common.mustCall (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/parallel/test-cli-syntax.js:97:14)
        at /home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:346:15
        at ChildProcess.exithandler (child_process.js:301:5)
        at ChildProcess.emit (events.js:189:13)
        at maybeClose (internal/child_process.js:977:16)
        at Socket.stream.socket.on (internal/child_process.js:395:11)
        at Socket.emit (events.js:189:13)
        at Pipe._handle.close (net.js:612:12)
  ...
Trott picture Trott on 5 Dec 2018

@Fishrock123 @MylesBorins @Trott Yes, there’s not much point in this output by itself. What might actually help is core dumps + the accompanying binaries.

addaleax picture addaleax on 5 Dec 2018

Because this test spawns so many subprocesses asynchronously, it's very easy to recreate this test failing both in the ways reported above and other ways. 

$ tools/test.py -j 32 --repeat 32 test/parallel/test-cli-syntax.js 
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
out/Release/node[62754]: ../src/spawn_sync.cc:464:Maybe<bool> node::SyncProcessRunner::TryInitializeAndRunLoop(Local<v8::Value>): Assertion `(uv_loop_init(uv_loop_)) == (0)' failed.
 1: 0x10005f18b node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005f0c8 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000d78a3 node::SyncProcessRunner::TryInitializeAndRunLoop(v8::Local<v8::Value>) [/Users/trott/io.js/out/Release/node]
 4: 0x1000d7534 node::SyncProcessRunner::Run(v8::Local<v8::Value>) [/Users/trott/io.js/out/Release/node]
 5: 0x1000d7429 node::SyncProcessRunner::Spawn(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 6: 0x10022df6b v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 7: 0x10022d48d v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 8: 0x10022cbdc v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 9: 0x100dea84e v8_Default_embedded_blob_ [/Users/trott/io.js/out/Release/node]
10: 0x12bdae20816e 
11: 0x12bdae20816e
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
--- CRASHED (Signal: 6) ---
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
out/Release/node[62761]: ../src/spawn_sync.cc:464:Maybe<bool> node::SyncProcessRunner::TryInitializeAndRunLoop(Local<v8::Value>): Assertion `(uv_loop_init(uv_loop_)) == (0)' failed.
 1: 0x10005f18b node::Abort() [/Users/trott/io.js/out/Release/node]
 2: 0x10005f0c8 node::PrintErrorString(char const*, ...) [/Users/trott/io.js/out/Release/node]
 3: 0x1000d78a3 node::SyncProcessRunner::TryInitializeAndRunLoop(v8::Local<v8::Value>) [/Users/trott/io.js/out/Release/node]
 4: 0x1000d7534 node::SyncProcessRunner::Run(v8::Local<v8::Value>) [/Users/trott/io.js/out/Release/node]
 5: 0x1000d7429 node::SyncProcessRunner::Spawn(v8::FunctionCallbackInfo<v8::Value> const&) [/Users/trott/io.js/out/Release/node]
 6: 0x10022df6b v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo*) [/Users/trott/io.js/out/Release/node]
 7: 0x10022d48d v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) [/Users/trott/io.js/out/Release/node]
 8: 0x10022cbdc v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) [/Users/trott/io.js/out/Release/node]
 9: 0x100dea84e v8_Default_embedded_blob_ [/Users/trott/io.js/out/Release/node]
10: 0x319db550816e 
11: 0x319db550816e
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
--- CRASHED (Signal: 6) ---
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== 0

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:112:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== ''

    at /Users/trott/io.js/test/parallel/test-cli-syntax.js:109:10
    at Array.forEach (<anonymous>)
    at Object.<anonymous> (/Users/trott/io.js/test/parallel/test-cli-syntax.js:104:12)
    at Module._compile (internal/modules/cjs/loader.js:723:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:734:10)
    at Module.load (internal/modules/cjs/loader.js:620:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:560:12)
    at Function.Module._load (internal/modules/cjs/loader.js:552:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:776:12)
    at executeUserCode (internal/bootstrap/node.js:341:15)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
-- stdout --

-- stderr --
assert.js:753
    throw newErr;
    ^

AssertionError [ERR_ASSERTION]: ifError got unwanted exception: spawn /bin/sh ENFILE
    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:43:14)
    at /Users/trott/io.js/test/common/index.js:346:15
    at exithandler (child_process.js:301:5)
    at ChildProcess.errorhandler (child_process.js:313:5)
    at ChildProcess.emit (events.js:189:13)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:252:12)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:246:19)
    at onErrorNT (internal/child_process.js:422:16)
    at internalTickCallback (internal/process/next_tick.js:72:19)
    at process._tickCallback (internal/process/next_tick.js:47:5)
    at Function.Module.runMain (internal/modules/cjs/loader.js:779:11)
    at executeUserCode (internal/bootstrap/node.js:341:15)
    at startExecution (internal/bootstrap/node.js:275:3)
    at startup (internal/bootstrap/node.js:226:3)
    at internal/bootstrap/node.js:706:1
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

null !== 1

    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:65:14)
    at /Users/trott/io.js/test/common/index.js:346:15
    at ChildProcess.exithandler (child_process.js:301:5)
    at ChildProcess.emit (events.js:189:13)
    at maybeClose (internal/child_process.js:978:16)
    at Socket.stream.socket.on (internal/child_process.js:396:11)
    at Socket.emit (events.js:189:13)
    at Pipe._handle.close (net.js:612:12)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

'ENFILE' !== 1

    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:65:14)
    at /Users/trott/io.js/test/common/index.js:346:15
    at exithandler (child_process.js:301:5)
    at ChildProcess.errorhandler (child_process.js:313:5)
    at ChildProcess.emit (events.js:189:13)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:252:12)
    at onErrorNT (internal/child_process.js:422:16)
    at internalTickCallback (internal/process/next_tick.js:72:19)
    at process._tickCallback (internal/process/next_tick.js:47:5)
    at Function.Module.runMain (internal/modules/cjs/loader.js:779:11)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:351
    throw err;
    ^

AssertionError [ERR_ASSERTION]: /^SyntaxError: \b/m === fs.js:121
    throw err;
    ^

Error: ENFILE: file table overflow, open '/Users/trott/io.js/test/fixtures/syntax/bad_syntax_shebang.js'
    at Object.openSync (fs.js:450:3)
    at Object.readFileSync (fs.js:350:35)
    at executeUserCode (internal/bootstrap/node.js:332:25)
    at startExecution (internal/bootstrap/node.js:275:3)
    at startup (internal/bootstrap/node.js:226:3)
    at internal/bootstrap/node.js:706:1

    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:71:7)
    at /Users/trott/io.js/test/common/index.js:346:15
    at ChildProcess.exithandler (child_process.js:301:5)
    at ChildProcess.emit (events.js:189:13)
    at maybeClose (internal/child_process.js:978:16)
    at Socket.stream.socket.on (internal/child_process.js:396:11)
    at Socket.emit (events.js:189:13)
    at Pipe._handle.close (net.js:612:12)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
-- stdout --

-- stderr --
assert.js:753
    throw newErr;
    ^

AssertionError [ERR_ASSERTION]: ifError got unwanted exception: spawn /bin/sh EAGAIN
    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:43:14)
    at /Users/trott/io.js/test/common/index.js:346:15
    at exithandler (child_process.js:301:5)
    at ChildProcess.errorhandler (child_process.js:313:5)
    at ChildProcess.emit (events.js:189:13)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:252:12)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:246:19)
    at onErrorNT (internal/child_process.js:422:16)
    at internalTickCallback (internal/process/next_tick.js:72:19)
    at process._tickCallback (internal/process/next_tick.js:47:5)
    at Function.Module.runMain (internal/modules/cjs/loader.js:779:11)
    at executeUserCode (internal/bootstrap/node.js:341:15)
    at startExecution (internal/bootstrap/node.js:275:3)
    at startup (internal/bootstrap/node.js:226:3)
    at internal/bootstrap/node.js:706:1
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
assert.js:86
  throw new AssertionError(obj);
  ^

AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:

'EAGAIN' !== 1

    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:65:14)
    at /Users/trott/io.js/test/common/index.js:346:15
    at exithandler (child_process.js:301:5)
    at ChildProcess.errorhandler (child_process.js:313:5)
    at ChildProcess.emit (events.js:189:13)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:252:12)
    at onErrorNT (internal/child_process.js:422:16)
    at internalTickCallback (internal/process/next_tick.js:72:19)
    at process._tickCallback (internal/process/next_tick.js:47:5)
    at Function.Module.runMain (internal/modules/cjs/loader.js:779:11)
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
=== release test-cli-syntax ===                   
Path: parallel/test-cli-syntax
-- stdout --

-- stderr --
assert.js:753
    throw newErr;
    ^

AssertionError [ERR_ASSERTION]: ifError got unwanted exception: spawn /bin/sh EAGAIN
    at common.mustCall (/Users/trott/io.js/test/parallel/test-cli-syntax.js:43:14)
    at /Users/trott/io.js/test/common/index.js:346:15
    at exithandler (child_process.js:301:5)
    at ChildProcess.errorhandler (child_process.js:313:5)
    at ChildProcess.emit (events.js:189:13)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:252:12)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:246:19)
    at onErrorNT (internal/child_process.js:422:16)
    at internalTickCallback (internal/process/next_tick.js:72:19)
    at process._tickCallback (internal/process/next_tick.js:47:5)
    at Function.Module.runMain (internal/modules/cjs/loader.js:779:11)
    at executeUserCode (internal/bootstrap/node.js:341:15)
    at startExecution (internal/bootstrap/node.js:275:3)
    at startup (internal/bootstrap/node.js:226:3)
    at internal/bootstrap/node.js:706:1
Command: out/Release/node /Users/trott/io.js/test/parallel/test-cli-syntax.js
[00:18|% 100|+   7|-  25]: Done                   
$

Trott picture Trott on 7 Dec 2018

Stress test to see if just running the test by itself results in failures: https://ci.nodejs.org/job/node-stress-single-test/2120/

RUN_TEST: parallel/test-cli-syntax
RUN_TIMES: 1000
RUN_LABLE: alpine-last-latest-x64

Trott picture Trott on 7 Dec 2018

Stress test to see if just running the test by itself results in failures: https://ci.nodejs.org/job/node-stress-single-test/2120/

Uh oh! Looks like some recent changes that @gabrielschulhof made to the Makefile need to be replicated in Jenkins maybe? @nodejs/build 

08:40:52 + make build-addons-napi
08:40:52 make: *** No rule to make target 'build-addons-napi'.  Stop.
08:40:52 Build step 'Conditional steps (multiple)' marked build as failure
08:40:52 Recording test results
08:40:52 Notifying upstream projects of job completion
08:40:52 Finished: FAILURE
Trott picture Trott on 7 Dec 2018

OK, I think I fixed the Jenkins issue, so hopefully back to looking at what's up with this test. Let's try again:

Stress test to see if just running the test by itself results in failures: https://ci.nodejs.org/job/node-stress-single-test/2121/

RUN_TEST: parallel/test-cli-syntax
RUN_TIMES: 1000
RUN_LABLE: alpine-last-latest-x64

Trott picture Trott on 7 Dec 2018

15 failures of all different kinds, including segmentation faults. Output says core dumped. @nodejs/build Can anyone retrieve a core file?

-- stdout --

-- stderr --
Segmentation fault (core dumped)

assert.js:753
    throw newErr;
    ^

AssertionError [ERR_ASSERTION]: ifError got unwanted exception: Command failed: /home/iojs/build/workspace/node-stress-single-test/nodes/alpine-last-latest-x64/out/Release/node -c /home/iojs/build/workspace/node-stress-single-test/nodes/alpine-last-latest-x64/test/fixtures/syntax/good_syntax.js
Segmentation fault (core dumped)

    at ChildProcess.exithandler (child_process.js:294:12)
    at ChildProcess.emit (events.js:189:13)
    at maybeClose (internal/child_process.js:978:16)
    at Socket.stream.socket.on (internal/child_process.js:396:11)
    at Socket.emit (events.js:189:13)
    at Pipe._handle.close (net.js:612:12)
Trott picture Trott on 7 Dec 2018

Moving to sequential, at least until this is sorted out, should mitigate the situation, which is getting a bit out of hand. I'll open a PR to do that.

Trott picture Trott on 8 Dec 2018

This test spawns 30 other node processes asynchronously and 4 synchronously. That seems like a lot, especially for things like containers, and maybe it needs to be split into a few different test files? Although even if it's exhausting resources and failing to spawn for that reason, I guess we'd still expect the failures to be helpful and not, say, crashing?

Trott picture Trott on 9 Dec 2018

Splitting the test into multiple files to see if it still fails. If not, it's probably creating too many processes. If so, then we (hopefully) isolate which part of the test is causing issues.

Trott picture Trott on 9 Dec 2018

https://github.com/nodejs/node/pull/24922 ^^^^

Trott picture Trott on 9 Dec 2018

If not, it's probably creating too many processes.

@trott I think we have a pretty good understanding of why this test fails, this just does require putting quite a bit of thought into a good solution. This may improve reliability, but there is at least one real bug in Node.js that’s being exposed here; it’s definitely not a resource exhaustion thing.

addaleax picture addaleax on 9 Dec 2018
👍1

this just does require putting quite a bit of thought into a good solution.

Yeah, if a good solution is likely forthcoming soon-ish, then yeah, marking it flaky for now or doing nothing is probably better than splitting it up. (Although splitting it up is quite possibly a good idea anyway for other reasons.)

Trott picture Trott on 9 Dec 2018

Although splitting it up is quite possibly a good idea anyway for other reasons.

Do you have more thoughts on that? I’d personally have a strong preference for reverting whatever changes we make to the test now once there is a real fix… it’s usually a good thing to have real bugs expose themselves as often as possible, right?

addaleax picture addaleax on 9 Dec 2018

Do you have more thoughts on that? I’d personally have a strong preference for reverting whatever changes we make to the test now once there is a real fix… it’s usually a good thing to have real bugs expose themselves as often as possible, right?

Rambling a bit here and probably being imprecise, but just to answer quickly: Assuming splitting it up does not increase reliability and this is not about resource exhaustion, I prefer test files to be narrowly-focused. We have a tendency to bolt on test cases in existing test files, sometimes in ways that make it harder to know what the original test was testing. This can have a few other undesirable effects. First, it can introduce subtle bugs in the tests due to side effects. Second, it can make the test more likely to time out if it's in the parallel directory. Third, it can make the test results harder to interpret, although I guess you can put that under side effects. Fourth, it can result in intimidatingly-long test files that are difficult to maintain. Although you could make the case that having thousands of files doesn't make that easier. But I think looking at one test file at a time is the more common situation.

Trott picture Trott on 9 Dec 2018
👍1

Here is a smaller version of the test that reliably fails in AIX and Linux. The more you run, the more variety of scenarios you get: SIGSEGV, SIGABRT, SIGILL... depends on at what point the main and the worker threads are.

'use strict'
const { Worker, isMainThread, parentPort } = require('worker_threads')

if (isMainThread) {
  const count = process.argv[2] / 1
  for(var i=0;i<count;i++)
    new Worker(__filename)
  process.exit(0)
} else {
  setInterval(() => {
    parentPort.postMessage('Hello, world!')
  }, 1)
}

AIX:

(gdb) r --experimental-worker foo.js 30
Starting program: node --experimental-worker foo.js 30
c[New Thread 1]

[New Thread 258]
[New Thread 515]
[New Thread 772]
[New Thread 1029]
[New Thread 1286]
[New Thread 1543]
[New Thread 1800]
[New Thread 2057]
[New Thread 2314]
[New Thread 2571]
[New Thread 2828]
[New Thread 3085]
[New Thread 3342]
[New Thread 3599]
[New Thread 3856]
[New Thread 4113]
[New Thread 4370]
[New Thread 4627]
[New Thread 4884]
[New Thread 5141]
[New Thread 5398]
[New Thread 5655]
[New Thread 5912]
[New Thread 6169]
[New Thread 6426]
[New Thread 6683]
[New Thread 6940]
[New Thread 7197]
[New Thread 7454]
[New Thread 7711]
[New Thread 7968]
[New Thread 8225]
[New Thread 8482]
[New Thread 8739]
[New Thread 8996]
[Switching to Thread 1]

Breakpoint 2, 0x0900000000037454 in exit () from /usr/lib/libc.a(shr_64.o)
(gdb) c
Continuing.
node[13369436]: ../src/node_native_module.cc:87:v8::Local<v8::String> node::native_module::NativeModuleLoader::GetSource(v8::Isolate*, const char*) const: Assertion `(it) != (source_.end())' failed.
node[13369436]: ../src/node_native_module.cc:87:v8::Local<v8::String> node::native_module::NativeModuleLoader::GetSource(v8::Isolate*, const char*) const: Assertion `(it) != (source_.end())' failed.

Program received signal SIGABRT, Aborted.
0x0000000100017818 in uv__close (fd=5) at ../deps/uv/src/unix/core.c:526
526     in ../deps/uv/src/unix/core.c
(gdb) info thr
  Id   Target Id         Frame 
  37   Thread 8996 (tid 86442081, running) 0x00000001000563f0 in v8::base::OS::SetPermissions(void*, unsigned long, v8::base::OS::MemoryPermission) ()
  36   Thread 8739 (tid 75169883, running) 0x0000000000000000 in ?? ()
  35   Thread 8482 (tid 83558431, running) 0x00000001000563f0 in v8::base::OS::SetPermissions(void*, unsigned long, v8::base::OS::MemoryPermission) ()
  34   Thread 8225 (tid 51445985, running) 0x0900000000514eb4 in pthread_kill ()
   from /usr/lib/libpthreads.a(shr_xpg5_64.o)
  33   Thread 7968 (tid 41484533, running) 0x000000000000f4d8 in ?? ()
  32   Thread 7711 (tid 32047309, running) 0x00000001000563f0 in v8::base::OS::SetPermissions(void*, unsigned long, v8::base::OS::MemoryPermission) ()
  31   Thread 7454 (tid 58261675, running) 0x0000000000000000 in ?? ()
  30   Thread 7197 (tid 58851527, running) 0x0000000000000000 in ?? ()
  29   Thread 6940 (tid 80412713, running) 0x0000000000000000 in ?? ()
  28   Thread 6683 (tid 93782211, running) 0x0000000000000000 in ?? ()
  27   Thread 6426 (tid 51511327, running) 0x0000000000000000 in ?? ()
  26   Thread 6169 (tid 31064175, running) 0x0000000000000000 in ?? ()
  25   Thread 5912 (tid 58654925, running) 0x0000000000000000 in ?? ()
  24   Thread 5655 (tid 19136757, running) 0x0000000000000000 in ?? ()
  23   Thread 5398 (tid 69664845, running) 0x0000000000000000 in ?? ()
  22   Thread 5141 (tid 53215451, running) 0x0000000000000000 in ?? ()
  21   Thread 4884 (tid 67371153, running) 0x0000000000000000 in ?? ()
  20   Thread 4627 (tid 94044409, running) 0x0000000000000000 in ?? ()
  19   Thread 4370 (tid 88277101, running) 0x0000000000000000 in ?? ()
  18   Thread 4113 (tid 50593905, running) 0x00000001005676ec in v8::internal::compiler::JSGraph::Constant(v8::internal::Handle<v8::internal::Object>) ()
  17   Thread 3856 (tid 61145117, running) 0x0000000000000000 in ?? ()
---Type <return> to continue, or q <return> to quit---
  16   Thread 3599 (tid 35192987, running) 0x0000000000000000 in ?? ()
  15   Thread 3342 (tid 60948543, running) 0x0000000000000000 in ?? ()
  14   Thread 3085 (tid 63045723, running) 0x0000000000000000 in ?? ()
  13   Thread 2828 (tid 11272293, running) 0x0000000000000000 in ?? ()
  12   Thread 2571 (tid 46530611, running) 0x0000000000000000 in ?? ()
  11   Thread 2314 (tid 61014237, running) 0x0000000000000000 in ?? ()
  10   Thread 2057 (tid 44499061, running) 0x0000000000000000 in ?? ()
  9    Thread 1800 (tid 58327291, running) 0x0000000000000000 in ?? ()
  8    Thread 1543 (tid 86048861, running) 0x0000000000000000 in ?? ()
  7    Thread 1286 (tid 91684907, sleeping) 0x0000000000000000 in ?? ()
  6    Thread 1029 (tid 22216839, sleeping) 0x0000000000000000 in ?? ()
  5    Thread 772 (tid 90701997, sleeping) 0x0000000000000000 in ?? ()
  4    Thread 515 (tid 91160731, sleeping) 0x0000000000000000 in ?? ()
  3    Thread 258 (tid 12189837, running) 0x0000000000000000 in ?? ()
* 2    Thread 1 (tid 76415137, running) 0x0000000100017818 in uv__close (fd=5)
    at ../deps/uv/src/unix/core.c:526
  1    process 13369436  0x0900000000514eb4 in pthread_kill ()
   from /usr/lib/libpthreads.a(shr_xpg5_64.o)
(gdb) where
#0  0x0000000100017818 in uv__close (fd=5) at ../deps/uv/src/unix/core.c:526
#1  0x0000000100e24700 in global destructors keyed to 65535_0_uv__signal_global_once_init ()
#2  0x0000000100e24910 in _GLOBAL__FD_node ()
#3  0x09fffffff00026a8 in mod_fini1 () from /usr/ccs/bin/usla64
#4  0x09fffffff000349c in usl_fini_mods () from /usr/ccs/bin/usla64
#5  0x09fffffff0003270 in usl_exit_fini_mods () from /usr/ccs/bin/usla64
#6  0x0900000000000974 in __modfini64 () from /usr/lib/libc.a(shr_64.o)
#7  0x09000000000375e0 in exit () from /usr/lib/libc.a(shr_64.o)
#8  0x0000000100742ed8 in node::Environment::Exit(int) ()
#9  0x0000000100000cd0 in node::Exit(v8::FunctionCallbackInfo<v8::Value> const&) ()
#10 0x0000000100047eac in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) ()
#11 0x00000001000450cc in v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) ()
#12 0x0700000000087c4c in ?? ()
(gdb)

Linux:

(gdb) r --experimental-worker foo.js 1
Starting program: node --experimental-worker foo.js 1
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
[New Thread 0x7ffff6bc6700 (LWP 34815)]
[New Thread 0x7ffff63c5700 (LWP 34816)]
[New Thread 0x7ffff5bc4700 (LWP 34817)]
[New Thread 0x7ffff53c3700 (LWP 34818)]
[New Thread 0x7ffff4bc2700 (LWP 34819)]
[New Thread 0x7ffff7ff8700 (LWP 34820)]
[New Thread 0x7fffdffff700 (LWP 34831)]

Breakpoint 1, 0x00007ffff6c00ba0 in exit () from /lib64/libc.so.6
(gdb) where
#0  0x00007ffff6c00ba0 in exit () from /lib64/libc.so.6
#1  0x0000000000920301 in node::Environment::Exit(int) ()
#2  0x0000000000949a80 in node::Exit(v8::FunctionCallbackInfo<v8::Value> const&) ()
#3  0x0000000000bdd058 in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) ()
#4  0x0000000000bdda76 in v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) ()
#5  0x000000000194b8ae in Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit ()
#6  0x000005ce46f8816e in ?? ()
#7  0x00000fdb2ee825a1 in ?? ()
#8  0x000021e9d7b22d19 in ?? ()
#9  0x0000000600000000 in ?? ()
#10 0x00000fdb2ee82681 in ?? ()
#11 0x0000000000000000 in ?? ()
(gdb) info thr
  Id   Target Id         Frame 
  8    Thread 0x7fffdffff700 (LWP 34831) "node" 0x0000000000f4cef8 in v8::internal::Factory::NewStruct(v8::internal::InstanceType, v8::internal::PretenureFlag) ()
  7    Thread 0x7ffff7ff8700 (LWP 34820) "node" 0x00007ffff6f9f945 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  6    Thread 0x7ffff4bc2700 (LWP 34819) "node" 0x00007ffff6f9f945 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  5    Thread 0x7ffff53c3700 (LWP 34818) "node" 0x00007ffff6f9f945 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  4    Thread 0x7ffff5bc4700 (LWP 34817) "node" 0x00007ffff6f9f945 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  3    Thread 0x7ffff63c5700 (LWP 34816) "node" 0x00007ffff6f9f945 in pthread_cond_wait@@GLIBC_2.3.2 ()
   from /lib64/libpthread.so.0
  2    Thread 0x7ffff6bc6700 (LWP 34815) "node" 0x00007ffff6cc5d77 in epoll_pwait ()
   from /lib64/libc.so.6
* 1    Thread 0x7ffff7fd8780 (LWP 34808) "node" 0x00007ffff6c00ba0 in exit () from /lib64/libc.so.6
(gdb) c
Continuing.

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffdffff700 (LWP 34831)]
0x00000000025d6b50 in ?? ()
(gdb) where
#0  0x00000000025d6b50 in ?? ()
#1  0x0000000000908de3 in node::AsyncWrap::AsyncReset(double, bool) ()
#2  0x000000000092c3cc in node::HandleWrap::HandleWrap(node::Environment*, v8::Local<v8::Object>, uv_handle_s*, node::AsyncWrap::ProviderType) ()
#3  0x00000000009bc23e in node::worker::MessagePort::MessagePort(node::Environment*, v8::Local<v8::Context>, v8::Local<v8::Object>) ()
#4  0x00000000009bc3af in node::worker::MessagePort::New(v8::FunctionCallbackInfo<v8::Value> const&) ()
#5  0x0000000000bdbea3 in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<true>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) ()
#6  0x0000000000bddcfa in v8::internal::Builtins::InvokeApiFunction(v8::internal::Isolate*, bool, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::Handle<v8::internal::HeapObject>) ()
#7  0x0000000000f199f9 in v8::internal::Execution::New(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) ()
#8  0x0000000000b69729 in v8::Function::NewInstanceWithSideEffectType(v8::Local<v8::Context>, int, v8::Local<v8::Value>*, v8::SideEffectType) const ()
#9  0x0000000000b699ec in v8::Function::NewInstance(v8::Local<v8::Context>, int, v8::Local<v8::Value>*) const ()
#10 0x00000000009bb425 in node::worker::MessagePort::New(node::Environment*, v8::Local<v8::Context>, std::unique_ptr<node::worker::MessagePortData, std::default_delete<node::worker::MessagePortData> >) ()
#11 0x00000000009fa9da in node::worker::Worker::Run() ()
#12 0x00007ffff6f9bdd5 in start_thread () from /lib64/libpthread.so.0
#13 0x00007ffff6cc5b3d in clone () from /lib64/libc.so.6
(gdb)

I guess before main thread exits, we need to do one of:

  • send message to workers to quiesce (potential deadlock, if we do at JS level)
  • hard exit (_exit), and workaround any side effects thereon (no atexit callback)
  • send message to worker threads to quiesce (through an interrupt routine may be)
  • limit global destructors to be executable only by main thread
gireeshpunathil picture gireeshpunathil on 10 Dec 2018

Should we open a separate issue for the destruction race condition? I think that counts as a confirmed bug?

joyeecheung picture joyeecheung on 12 Dec 2018
👍1

Some of these failing tests have been modified to try to produce more information, but alas, nothing useful in this case. All the error message stuff after null !== 1 in the output below is (I believe) the error that is expected by the test. It is just the code that is missing/wrong, which we already knew.

https://ci.nodejs.org/job/node-test-commit-aix/19747/nodes=aix61-ppc64/console

test-osuosl-aix61-ppc64_be-2

01:44:30 not ok 2391 sequential/test-cli-syntax-file-not-found # TODO : Fix flaky test
01:44:30   ---
01:44:30   duration_ms: 3.206
01:44:30   severity: flaky
01:44:30   exitcode: 1
01:44:30   stack: |-
01:44:30     assert.js:86
01:44:30       throw new AssertionError(obj);
01:44:30       ^
01:44:30     
01:44:30     AssertionError [ERR_ASSERTION]: code null !== 1 for error:
01:44:30     
01:44:30     Error: Command failed: /home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/out/Release/node -c /home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/fixtures/syntax/file_not_found.js
01:44:30     internal/modules/cjs/loader.js:602
01:44:30         throw err;
01:44:30         ^
01:44:30     
01:44:30     Error: Cannot find module '/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/fixtures/syntax/file_not_found.js'
01:44:30         at Function.Module._resolveFilename (internal/modules/cjs/loader.js:600:15)
01:44:30         at executeUserCode (internal/bootstrap/node.js:307:34)
01:44:30         at startExecution (internal/bootstrap/node.js:251:3)
01:44:30         at startup (internal/bootstrap/node.js:202:3)
01:44:30         at internal/bootstrap/node.js:692:1
01:44:30     
01:44:30         at common.mustCall (/home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/sequential/test-cli-syntax-file-not-found.js:36:14)
01:44:30         at /home/iojs/build/workspace/node-test-commit-aix/nodes/aix61-ppc64/test/common/index.js:335:15
01:44:30         at ChildProcess.exithandler (child_process.js:301:5)
01:44:30         at ChildProcess.emit (events.js:189:13)
01:44:30         at maybeClose (internal/child_process.js:978:16)
01:44:30         at Socket.stream.socket.on (internal/child_process.js:396:11)
01:44:30         at Socket.emit (events.js:189:13)
01:44:30         at Pipe._handle.close (net.js:612:12)
01:44:30   ...
Trott picture Trott on 15 Dec 2018

@trott I don’t think we’ll find useful information on the JS side… maybe this is a good reason to figure out a way to make core dumps from CI available for download somehow?

addaleax picture addaleax on 15 Dec 2018
👍1

this should be good to close now; ncu data did now show this up.
cc @refack @Trott

gireeshpunathil picture gireeshpunathil on 5 Feb 2019

Agreed: Not seeing it in ncu-ci data. Closing. Obviously, re-open if I'm wrong.

Trott picture Trott on 5 Feb 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

filipesilvaa picture filipesilvaa  Â·  3Comments
danielstaleiny picture danielstaleiny  Â·  3Comments
sandeepks1 picture sandeepks1  Â·  3Comments
fanjunzhi picture fanjunzhi  Â·  3Comments
seishun picture seishun  Â·  3Comments