Skip to content

test/parallel/test-async-wrap-getasyncid.js crashing #14599

New issue

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

#

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

Already on GitHub? # to your account

Jump to bottom
Closed
matthewloring opened this issue Aug 2, 2017 · 10 comments
Closed

test/parallel/test-async-wrap-getasyncid.js crashing #14599

matthewloring opened this issue Aug 2, 2017 · 10 comments
Labels
dns Issues and PRs related to the dns subsystem.

Comments

@matthewloring
Copy link

  • Version: master
  • Platform: mac 10.12.6/ubuntu 14.04 tested so far
  • Subsystem: async wrap

Example asan output

==85389==ERROR: AddressSanitizer: heap-use-after-free on address 0x6110000b3e18 at pc 0x00000a51049f bp 0x7ffe6b4cd670 sp 0x7ffe6b4cd668
WRITE of size 8 at 0x6110000b3e18 thread T0
    #0 0xa51049e in uv__finish_close /out/../deps/uv/src/unix/core.c:277:3
    #1 0xa4fc776 in uv__run_closing_handles /out/../deps/uv/src/unix/core.c:294:5
    #2 0xa4fb23e in uv_run /out/../deps/uv/src/unix/core.c:364:5
    #3 0x939ff38 in node::Start(v8::Isolate*, node::IsolateData*, int, char const* const*, int, char const* const*) /out/../src/node.cc:4543:14
    #4 0x939a7cc in node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) /out/../src/node.cc:4607:17
    #5 0x93781b2 in node::Start(int, char**) /out/../src/node.cc:4662:7
    #6 0x958ebb8 in main /out/../src/node_main.cc:104:10
    #7 0x7f9d69ea4f44 in __libc_start_main /build/eglibc-SvCtMH/eglibc-2.19/csu/libc-start.c:287
    #8 0x1417e1c in _start (/out/Debug/node+0x1417e1c)

0x6110000b3e18 is located 88 bytes inside of 224-byte region [0x6110000b3dc0,0x6110000b3ea0)
freed by thread T0 here:
    #0 0x139344b in operator delete(void*) (/out/Debug/node+0x139344b)
    #1 0x92c88b1 in node::cares_wrap::(anonymous namespace)::ChannelWrap::~ChannelWrap() /out/../src/cares_wrap.cc:523:29
    #2 0x92c927a in void node::BaseObject::WeakCallback<node::cares_wrap::(anonymous namespace)::ChannelWrap>(v8::WeakCallbackInfo<node::cares_wrap::(anonymous namespace)::ChannelWrap> const&) /out/../src/base-object-inl.h:72:3
    #3 0x63ca955 in v8::internal::GlobalHandles::PendingPhantomCallback::Invoke(v8::internal::Isolate*) /out/../deps/v8/src/global-handles.cc:835:3
    #4 0x63ce033 in v8::internal::GlobalHandles::DispatchPendingPhantomCallbacks(bool) /out/../deps/v8/src/global-handles.cc:800:7
    #5 0x63d022b in v8::internal::GlobalHandles::PostGarbageCollectionProcessing(v8::internal::GarbageCollector, v8::GCCallbackFlags) /out/../deps/v8/src/global-handles.cc:856:18
    #6 0x64a8d1d in v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) /out/../deps/v8/src/heap/heap.cc:1389:9
    #7 0x64a4199 in v8::internal::Heap::CollectGarbage(v8::internal::GarbageCollector, v8::internal::GarbageCollectionReason, char const*, v8::GCCallbackFlags) /out/../deps/v8/src/heap/heap.cc:1023:11
    #8 0x2f6abba in v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) /out/../deps/v8/src/heap/heap-inl.h:681:10
    #9 0x6238aad in v8::internal::Factory::CopyJSObjectWithAllocationSite(v8::internal::Handle<v8::internal::JSObject>, v8::internal::Handle<v8::internal::AllocationSite>) /out/../deps/v8/src/factory.cc:1275:3
    #10 0x71ff834 in v8::internal::JSObjectWalkVisitor<v8::internal::AllocationSiteUsageContext>::StructureWalk(v8::internal::Handle<v8::internal::JSObject>) /out/../deps/v8/src/objects.cc:7938:12
    #11 0x71fe07f in v8::internal::JSObject::DeepCopy(v8::internal::Handle<v8::internal::JSObject>, v8::internal::AllocationSiteUsageContext*, v8::internal::JSObject::DeepCopyHints) /out/../deps/v8/src/objects.cc:8117:32
    #12 0x807a9d2 in v8::internal::__RT_impl_Runtime_CreateObjectLiteral(v8::internal::Arguments, v8::internal::Isolate*) /out/../deps/v8/src/runtime/runtime-literals.cc:255:7
    #13 0x8077fb5 in v8::internal::Runtime_CreateObjectLiteral(int, v8::internal::Object**, v8::internal::Isolate*) /out/../deps/v8/src/runtime/runtime-literals.cc:210:1
    #14 0x255f1f904563 (<unknown module>)
    #15 0x255f1facc72c (<unknown module>)
    #16 0x255f1fa0e104 (<unknown module>)
    #17 0x255f1f90675a (<unknown module>)
    #18 0x255f1fa85ab6 (<unknown module>)
    #19 0x255f1fa0e104 (<unknown module>)
    #20 0x255f1fa84f36 (<unknown module>)
    #21 0x255f1fa0e104 (<unknown module>)
    #22 0x255f1fa85149 (<unknown module>)
    #23 0x255f1fa0e104 (<unknown module>)
    #24 0x255f1fa84895 (<unknown module>)
    #25 0x255f1fa0e104 (<unknown module>)
    #26 0x255f1fa85149 (<unknown module>)
    #27 0x255f1fa0e104 (<unknown module>)
    #28 0x255f1fa85f5f (<unknown module>)
    #29 0x255f1fa0e104 (<unknown module>)

previously allocated by thread T0 here:
    #0 0x1392f0b in operator new(unsigned long) (/out/Debug/node+0x1392f0b)
    #1 0x9274b12 in node::cares_wrap::(anonymous namespace)::ChannelWrap::New(v8::FunctionCallbackInfo<v8::Value> const&) /out/../src/cares_wrap.cc:182:3
    #2 0x30a873c in v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) /out/../deps/v8/src/api-arguments.cc:25:3
    #3 0x367f215 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) /out/../deps/v8/src/builtins/builtins-api.cc:112:29
    #4 0x367aac5 in v8::internal::Builtin_Impl_HandleApiCall(v8::internal::BuiltinArguments, v8::internal::Isolate*) /out/../deps/v8/src/builtins/builtins-api.cc:138:5
    #5 0x3679317 in v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) /out/../deps/v8/src/builtins/builtins-api.cc:130:1
    #6 0x255f1f904563 (<unknown module>)
    #7 0x255f1fa0945c (<unknown module>)
    #8 0x255f1fa88c34 (<unknown module>)
    #9 0x255f1fa0e104 (<unknown module>)
    #10 0x255f1fa84895 (<unknown module>)
    #11 0x255f1fa0e104 (<unknown module>)
    #12 0x255f1fa85357 (<unknown module>)
    #13 0x255f1fa0e104 (<unknown module>)
    #14 0x255f1fa85357 (<unknown module>)
    #15 0x255f1fa0e104 (<unknown module>)
    #16 0x255f1fa85149 (<unknown module>)
    #17 0x255f1fa0e104 (<unknown module>)
    #18 0x255f1fa8616f (<unknown module>)
    #19 0x255f1fa0e104 (<unknown module>)
    #20 0x255f1fa84895 (<unknown module>)
    #21 0x255f1fa0e104 (<unknown module>)
    #22 0x255f1fabfb36 (<unknown module>)
    #23 0x255f1fa0e104 (<unknown module>)
    #24 0x255f1fa85d4e (<unknown module>)
    #25 0x255f1fa0e104 (<unknown module>)
    #26 0x255f1fa0c998 (<unknown module>)
    #27 0x255f1f90412c (<unknown module>)
    #28 0x616d642 in v8::internal::(anonymous namespace)::Invoke(v8::internal::Isolate*, bool, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::Handle<v8::internal::Object>, v8::internal::Execution::MessageHandling) /out/../deps/v8/src/execution.cc:145:13
    #29 0x616ad46 in v8::internal::(anonymous namespace)::CallInternal(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*, v8::internal::Execution::MessageHandling) /out/../deps/v8/src/execution.cc:181:10

SUMMARY: AddressSanitizer: heap-use-after-free /out/../deps/uv/src/unix/core.c:277 uv__finish_close
Shadow bytes around the buggy address:
  0x0c228000e770: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c228000e780: fd fd fd fd fd fd fd fd fa fa fa fa fa fa fa fa
  0x0c228000e790: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c228000e7a0: 00 00 00 00 00 00 00 00 00 00 00 00 fa fa fa fa
  0x0c228000e7b0: fa fa fa fa fa fa fa fa fd fd fd fd fd fd fd fd
=>0x0c228000e7c0: fd fd fd[fd]fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c228000e7d0: fd fd fd fd fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c228000e7e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
  0x0c228000e7f0: 00 00 00 00 00 00 00 00 00 00 fa fa fa fa fa fa
  0x0c228000e800: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c228000e810: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
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
  Heap right redzone:      fb
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack partial redzone:   f4
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  ASan internal:           fe
==85389==ABORTING
@mhdawson
Copy link
Member

mhdawson commented Aug 2, 2017

Seen on AIX as well
https://ci.nodejs.org/job/node-test-commit-aix/nodes=aix61-ppc64/7590/console
https://ci.nodejs.org/job/node-test-commit-aix/nodes=aix61-ppc64/7602/console

@matthewloring
Copy link
Author

/cc @nodejs/async_hooks

@refack
Copy link
Contributor

refack commented Aug 2, 2017

@matthewloring I'm assuming this is intermittent, right?
Also could you run with lldb or llnode with v8 bt so the JS frames will be resolved.

@matthewloring
Copy link
Author

I'm not sure the best way to capture a stack at the point where the leaked object is allocated/freed. As best I can tell the allocation happens with this stack:

frame #0: 0x00000001042a06b8 node`::New() at cares_wrap.cc:181
    frame #1: 0x0000000100d46049 node`::Call() at api-arguments.cc:25
    frame #2: 0x0000000101098c44 node`::HandleApiCallHelper<true>() at builtins-api.cc:112
    frame #3: 0x0000000101096116 node`::Builtin_Impl_HandleApiCall() at builtins-api.cc:138
    frame #4: 0x0000000101095444 node`::Builtin_HandleApiCall() at builtins-api.cc:130
    frame #27: 0x0000000102847e32 node`::Invoke() at execution.cc:145
    frame #28: 0x0000000102846741 node`::CallInternal() at execution.cc:181
    frame #29: 0x0000000102846087 node`::Call() at execution.cc:191
    frame #30: 0x0000000100c5ccd5 node`::Call() at api.cc:5279
    frame #31: 0x0000000100c5d39f node`::Call() at api.cc:5288
    frame #32: 0x000000010433f33c node`::LoadEnvironment() at node.cc:3615
    frame #33: 0x00000001043724bc node`::Start() at node.cc:4530
    frame #34: 0x000000010434811b node`::Start() at node.cc:4608
    frame #35: 0x000000010434709f node`::Start() at node.cc:4663
    frame #36: 0x000000010448a928 node`main at node_main.cc:104
    frame #37: 0x0000000100001a34 node`start + 52

and the free happens with this stack:

frame #0: 0x00000001042b9173 node`::~ChannelWrap() at cares_wrap.cc:524
    frame #1: 0x00000001042b0305 node`::~ChannelWrap() at cares_wrap.cc:523
    frame #2: 0x00000001042b0329 node`::~ChannelWrap() at cares_wrap.cc:523
    frame #3: 0x00000001042b069c node`::WeakCallback<node::cares_wrap::(anonymous namespace)::ChannelWrap>() at base-object-inl.h:72
    frame #4: 0x0000000102978426 node`::Invoke() at global-handles.cc:835
    frame #5: 0x00000001029798f6 node`::DispatchPendingPhantomCallbacks() at global-handles.cc:800
    frame #6: 0x000000010297a249 node`::PostGarbageCollectionProcessing() at global-handles.cc:856
    frame #7: 0x00000001029e382f node`::PerformGarbageCollection() at heap.cc:1389
    frame #8: 0x00000001029e17c9 node`::CollectGarbage() at heap.cc:1023
    frame #9: 0x0000000100cb78c6 node`::CollectGarbage() at heap-inl.h:681
    frame #10: 0x000000010287941a node`::NewFillerObject() at factory.cc:86
    frame #11: 0x0000000103804f19 node`::__RT_impl_Runtime_AllocateInNewSpace() at runtime-internal.cc:336
    frame #12: 0x000000010380447e node`::Runtime_AllocateInNewSpace() at runtime-internal.cc:329
    frame #48: 0x0000000102847e32 node`::Invoke() at execution.cc:145
    frame #49: 0x0000000102846741 node`::CallInternal() at execution.cc:181
    frame #50: 0x0000000102846087 node`::Call() at execution.cc:191
    frame #51: 0x0000000100c5ccd5 node`::Call() at api.cc:5279
    frame #52: 0x0000000100c5d39f node`::Call() at api.cc:5288
    frame #53: 0x000000010433f33c node`::LoadEnvironment() at node.cc:3615
    frame #54: 0x00000001043724bc node`::Start() at node.cc:4530
    frame #55: 0x000000010434811b node`::Start() at node.cc:4608
    frame #56: 0x000000010434709f node`::Start() at node.cc:4663
    frame #57: 0x000000010448a928 node`main at node_main.cc:104
    frame #58: 0x0000000100001a34 node`start + 52

But these aren't consistent with the stacks reported by asan.

@matthewloring
Copy link
Author

@refack I have been able to reproduce it on every asan run and it has shown up in every CI attempt on #14001 (non asan builds).

@refack refack added flaky-test Issues and PRs related to the tests with unstable failures on the CI. test Issues and PRs related to the tests. labels Aug 2, 2017
@refack
Copy link
Contributor

refack commented Aug 2, 2017

I'm marking as flaky and trying to investigate...

@tniessen
Copy link
Member

tniessen commented Aug 2, 2017 •
edited
Loading

/cc @addaleax as there are stack frames related to #14518 (ChannelWrap).

@Trott Trott mentioned this issue Aug 3, 2017
Closed
2 tasks
@addaleax addaleax added cares Issues and PRs related to the c-ares dependency or the cares_wrap binding. dns Issues and PRs related to the dns subsystem. and removed async_wrap flaky-test Issues and PRs related to the tests with unstable failures on the CI. test Issues and PRs related to the tests. cares Issues and PRs related to the c-ares dependency or the cares_wrap binding. labels Aug 4, 2017
addaleax added a commit to addaleax/node that referenced this issue Aug 4, 2017
@addaleax
src: properly manage timer in cares ChannelWrap
3baafef 
This fixes a bug introduced in 727b291
where code managing the `uv_timer_t` for a `ChannelWrap` instance was
left unchanged, when it should have changed the lifetime of the handle
to being tied to the `ChannelWrap` instance’s lifetime.

Fixes: nodejs#14599
Ref: nodejs#14518
@addaleax addaleax mentioned this issue Aug 4, 2017
Closed
3 tasks
@addaleax
Copy link
Member

addaleax commented Aug 4, 2017

Fix is in #14634, this really is my bad.

@refack refack mentioned this issue Aug 4, 2017
Closed
2 tasks
@Trott
Copy link
Member

Trott commented Aug 5, 2017

Now failing in FIPS mode! :-D

https://ci.nodejs.org/job/node-test-commit-linux-fips/10108/nodes=ubuntu1404-64/console

not ok 78 parallel/test-async-wrap-getasyncid
  ---
  duration_ms: 0.620
  severity: crashed
  stack: |-
    oh no!
    exit code: CRASHED (Signal: 11)

@matthewloring
Copy link
Author

@Trott The fix hasn't landed yet. Hopefully it will address things on FIPS as well.

addaleax added a commit that referenced this issue Aug 7, 2017
@addaleax
src: properly manage timer in cares ChannelWrap
3c6b5e5 
This fixes a bug introduced in 727b291
where code managing the `uv_timer_t` for a `ChannelWrap` instance was
left unchanged, when it should have changed the lifetime of the handle
to being tied to the `ChannelWrap` instance’s lifetime.

Fixes: #14599
Ref: #14518
PR-URL: #14634
Reviewed-By: Refael Ackermann <refack@gmail.com>
Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl>
Reviewed-By: Fedor Indutny <fedor.indutny@gmail.com>
Reviewed-By: James M Snell <jasnell@gmail.com>
Reviewed-By: Khaidi Chu <i@2333.moe>
Reviewed-By: Tobias Nießen <tniessen@tnie.de>
# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees
No one assigned
Labels
dns Issues and PRs related to the dns subsystem.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

src: properly manage timer in cares ChannelWrap addaleax/node
6 participants
@refack @Trott @addaleax @matthewloring @tniessen @mhdawson