make test: use after free: parallel/test-cli-node-options

[matthiaskrgr]

git repo (nodejs/node) @ 64de66d
I was running CFLAGS="-fsanitize=address -fno-sanitize=leak -g3" CXXFLAGS="$CFLAGS" LDFLAGS="-fsanitize=address -fno-sanitize=leak -g3" ASAN_OPTIONS=detect_leaks=0 make test -j 4
platform: Linux t470 4.17.0-2-MANJARO #1 SMP PREEMPT Fri Jun 8 07:13:17 UTC 2018 x86_64 GNU/Linux

I used clang 6.0 as CC/CXX.

During make test, I got a use after free:

[----------] Global test environment tear-down
[==========] 74 tests from 9 test cases ran. (424 ms total)
[  PASSED  ] 74 tests.
make -s jstest
  touch 251b41f63160e3e22459f6ddaeb4fca739404752.intermediate
  touch 1b6e683759875e45877a449826f87697ec02fb35.intermediate
  LD_LIBRARY_PATH=/home/matthias/vcs/github/node/out/Release/lib.host:/home/matthias/vcs/github/node/out/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../.; mkdir -p /home/matthias/vcs/github/node/out/Release/obj/gen/src/node/inspector/protocol; python deps/v8/third_party/inspector_protocol/CodeGenerator.py --jinja_dir deps/v8/third_party/inspector_protocol/.. --output_base "/home/matthias/vcs/github/node/out/Release/obj/gen/src/" --config "/home/matthias/vcs/github/node/out/Release/obj/gen/node_protocol_config.json"
  LD_LIBRARY_PATH=/home/matthias/vcs/github/node/out/Release/lib.host:/home/matthias/vcs/github/node/out/Release/lib.target:$LD_LIBRARY_PATH; export LD_LIBRARY_PATH; cd ../deps/v8/gypfiles; mkdir -p /home/matthias/vcs/github/node/out/Release/obj/gen/src/inspector/protocol /home/matthias/vcs/github/node/out/Release/obj/gen/include/inspector; python ../third_party/inspector_protocol/CodeGenerator.py --jinja_dir ../third_party --output_base "/home/matthias/vcs/github/node/out/Release/obj/gen/src/inspector" --config ../src/inspector/inspector_protocol_config.json
=== release test-cli-node-options ===
Path: parallel/test-cli-node-options
assert.js:671
    throw newErr;
    ^
AssertionError [ERR_ASSERTION]: ifError got unwanted exception: Command failed: /home/matthias/vcs/github/node/out/Release/node -e console.log("B")
=================================================================
==25285==ERROR: AddressSanitizer: heap-use-after-free on address 0x619000000ae0 at pc 0x000001a219ac bp 0x7f46b37fed10 sp 0x7f46b37fed08
READ of size 8 at 0x619000000ae0 thread T1
    #0 0x1a219ab in uv__run_closing_handles /home/matthias/vcs/github/node/out/../deps/uv/src/unix/core.c:299:12
    #1 0x1a219ab in uv_run /home/matthias/vcs/github/node/out/../deps/uv/src/unix/core.c:370
    #2 0x7f46b6490074 in start_thread (/usr/lib/libpthread.so.0+0x7074)
    #3 0x7f46b5fad53e in __GI___clone (/usr/lib/libc.so.6+0xf853e)
0x619000000ae0 is located 96 bytes inside of 952-byte region [0x619000000a80,0x619000000e38)
freed by thread T0 here:
    #0 0x16cbbe2 in operator delete(void*) /home/matthias/LLVM/LLVM6/stage_2/llvm/projects/compiler-rt/lib/asan/asan_new_delete.cc:149:3
    #1 0x18f762d in std::default_delete<node::tracing::AsyncTraceWriter>::operator()(node::tracing::AsyncTraceWriter*) const /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/unique_ptr.h:81:2
    #2 0x18f762d in std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> >::~unique_ptr() /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/unique_ptr.h:274
    #3 0x18f762d in std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >::~pair() /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/stl_pair.h:198
    #4 0x18f762d in void __gnu_cxx::new_allocator<std::__detail::_Hash_node<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, false> >::destroy<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > > >(std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >*) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/ext/new_allocator.h:140
    #5 0x18f762d in void std::allocator_traits<std::allocator<std::__detail::_Hash_node<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, false> > >::destroy<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > > >(std::allocator<std::__detail::_Hash_node<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, false> >&, std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >*) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/alloc_traits.h:487
    #6 0x18f762d in std::__detail::_Hashtable_alloc<std::allocator<std::__detail::_Hash_node<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, false> > >::_M_deallocate_node(std::__detail::_Hash_node<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, false>*) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/hashtable_policy.h:2100
    #7 0x18f762d in std::_Hashtable<int, std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, std::allocator<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > > >, std::__detail::_Select1st, std::equal_to<int>, std::hash<int>, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<false, false, true> >::_M_erase(unsigned long, std::__detail::_Hash_node_base*, std::__detail::_Hash_node<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, false>*) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/hashtable.h:1905
    #8 0x18f762d in std::_Hashtable<int, std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, std::allocator<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > > >, std::__detail::_Select1st, std::equal_to<int>, std::hash<int>, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<false, false, true> >::_M_erase(std::integral_constant<bool, true>, int const&) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/hashtable.h:1931
    #9 0x18f762d in std::_Hashtable<int, std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > >, std::allocator<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > > >, std::__detail::_Select1st, std::equal_to<int>, std::hash<int>, std::__detail::_Mod_range_hashing, std::__detail::_Default_ranged_hash, std::__detail::_Prime_rehash_policy, std::__detail::_Hashtable_traits<false, false, true> >::erase(int const&) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/hashtable.h:771
    #10 0x18f762d in std::unordered_map<int, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> >, std::hash<int>, std::equal_to<int>, std::allocator<std::pair<int const, std::unique_ptr<node::tracing::AsyncTraceWriter, std::default_delete<node::tracing::AsyncTraceWriter> > > > >::erase(int const&) /usr/lib64/gcc/x86_64-pc-linux-gnu/8.1.1/../../../../include/c++/8.1.1/bits/unordered_map.h:818
    #11 0x18f762d in node::tracing::Agent::Disconnect(int) /home/matthias/vcs/github/node/out/../src/tracing/agent.cc:100
    #12 0x18fb9a8 in node::tracing::Agent::DisconnectClient(std::pair<node::tracing::Agent*, int>*) /home/matthias/vcs/github/node/out/../src/tracing/agent.h:67:22
    #13 0x1770792 in node::$_0::StopTracingAgent() /home/matthias/vcs/github/node/out/../src/node.cc:334:23
    #14 0x1770792 in node::Start(int, char**) /home/matthias/vcs/github/node/out/../src/node.cc:3684
    #15 0x7f46b5ed806a in __libc_start_main (/usr/lib/libc.so.6+0x2306a)
previously allocated by thread T0 here:
    #0 0x16cb002 in operator new(unsigned long) /home/matthias/LLVM/LLVM6/stage_2/llvm/projects/compiler-rt/lib/asan/asan_new_delete.cc:92:3
    #1 0x18f93bf in node::tracing::Agent::Enable(std::set<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::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) /home/matthias/vcs/github/node/out/../src/tracing/agent.cc:137:9
    #2 0x18f857c in node::tracing::Agent::Enable(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) /home/matthias/vcs/github/node/out/../src/tracing/agent.cc:120:3
    #3 0x1770699 in node::$_0::StartTracingAgent() /home/matthias/vcs/github/node/out/../src/node.cc:329:21
    #4 0x1770699 in node::$_0::Initialize(int) /home/matthias/vcs/github/node/out/../src/node.cc:294
    #5 0x1770699 in node::Start(int, char**) /home/matthias/vcs/github/node/out/../src/node.cc:3678
    #6 0x7f46b5ed806a in __libc_start_main (/usr/lib/libc.so.6+0x2306a)
Thread T1 created by T0 here:
    #0 0x168601d in __interceptor_pthread_create /home/matthias/LLVM/LLVM6/stage_2/llvm/projects/compiler-rt/lib/asan/asan_interceptors.cc:204:3
    #1 0x1a4755b in uv_thread_create /home/matthias/vcs/github/node/out/../deps/uv/src/unix/thread.c:202:9
    #2 0x18f62de in node::tracing::Agent::Start() /home/matthias/vcs/github/node/out/../src/tracing/agent.cc:65:3
    #3 0x18f93b5 in node::tracing::Agent::Enable(std::set<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::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > > const&) /home/matthias/vcs/github/node/out/../src/tracing/agent.cc:135:5
    #4 0x18f857c in node::tracing::Agent::Enable(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) /home/matthias/vcs/github/node/out/../src/tracing/agent.cc:120:3
    #5 0x1770699 in node::$_0::StartTracingAgent() /home/matthias/vcs/github/node/out/../src/node.cc:329:21
    #6 0x1770699 in node::$_0::Initialize(int) /home/matthias/vcs/github/node/out/../src/node.cc:294
    #7 0x1770699 in node::Start(int, char**) /home/matthias/vcs/github/node/out/../src/node.cc:3678
    #8 0x7f46b5ed806a in __libc_start_main (/usr/lib/libc.so.6+0x2306a)
SUMMARY: AddressSanitizer: heap-use-after-free /home/matthias/vcs/github/node/out/../deps/uv/src/unix/core.c:299:12 in uv__run_closing_handles
Shadow bytes around the buggy address:
  0x0c327fff8100: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c327fff8110: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c327fff8120: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c327fff8130: 00 00 00 00 00 fa fa fa fa fa fa fa fa fa fa fa
  0x0c327fff8140: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
=>0x0c327fff8150: fd fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd fd
  0x0c327fff8160: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c327fff8170: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c327fff8180: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c327fff8190: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c327fff81a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==25285==ABORTING
    at ChildProcess.exithandler (child_process.js:291:12)
    at ChildProcess.emit (events.js:182:13)
    at maybeClose (internal/child_process.js:961:16)
    at Process.ChildProcess._handle.onexit (internal/child_process.js:248:5)
Command: out/Release/node /home/matthias/vcs/github/node/test/parallel/test-cli-node-options.js
=== release test-crypto-dh-leak ===
Path: parallel/test-crypto-dh-leak
assert.js:270
    throw err;
    ^
AssertionError [ERR_ASSERTION]: before=131252224 after=150888448
    at Object.<anonymous> (/home/matthias/vcs/github/node/test/parallel/test-crypto-dh-leak.js:26:1)
    at Module._compile (internal/modules/cjs/loader.js:702:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:713:10)
    at Module.load (internal/modules/cjs/loader.js:612:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:551:12)
    at Function.Module._load (internal/modules/cjs/loader.js:543:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:744:10)
    at startup (internal/bootstrap/node.js:241:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:565:3)
Command: out/Release/node --expose-gc --noconcurrent_recompilation /home/matthias/vcs/github/node/test/parallel/test-crypto-dh-leak.js

[bnoordhuis]

cc @eugeneo @ofrobots - I'm reasonably sure this is caused by freeing the memory of one of the uv_async_t handles prematurely.

At a guess, the signalling from the close callback needs to be delayed until both close callbacks have happened (applies to both node_trace_buffer.cc and node_trace_writer.cc.)

[eugeneo]

I think #21335 should fix it.

[Trott]

#21335 was closed without landing. Did an alternative land? Should this be closed?

If this is still a problem, might it be the source of this that comes up in CI on Windows 10:

00:57:06 not ok 71 parallel/test-cli-node-options
00:57:06   ---
00:57:06   duration_ms: 2.627
00:57:06   severity: fail
00:57:06   exitcode: 1
00:57:06   stack: |-
00:57:06     assert.js:753
00:57:06         throw newErr;
00:57:06         ^
00:57:06     
00:57:06     AssertionError [ERR_ASSERTION]: ifError got unwanted exception: Command failed: c:\workspace\node-test-binary-windows\Release\node.exe -e console.log("B")
00:57:06     
00:57:06         at ChildProcess.exithandler (child_process.js:294:12)
00:57:06         at ChildProcess.emit (events.js:189:13)
00:57:06         at maybeClose (internal/child_process.js:977:16)
00:57:06         at Process.ChildProcess._handle.onexit (internal/child_process.js:265:5)
00:57:06   ...

Above is from https://ci.nodejs.org/job/node-test-binary-windows/21941/COMPILED_BY=vs2017,RUNNER=win10,RUN_SUBSET=0/console and was on host test-azure_msft-win10-x64-4.

[jasnell]

@nodejs/build Has this been resolved?

[richardlau]

@nodejs/build Has this been resolved?

¯\_(ツ)_/¯ This doesn't look like a build issue. It looks like it was an issue with trace events.