Skip to content

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

Closed
Closed
test/parallel/test-async-wrap-getasyncid.js crashing#14599
Labels
dnsIssues and PRs related to the dns subsystem.

Description

@matthewloring
matthewloring
opened on Aug 2, 2017
  • 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

Activity

  1. mhdawson commented on Aug 2, 2017

    @mhdawson
    mhdawson
    on Aug 2, 2017
    Member

    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

  2. matthewloring commented on Aug 2, 2017

    @matthewloring
    matthewloring
    on Aug 2, 2017
    Author

    /cc @nodejs/async_hooks

  3. matthewloring
    added
    async_wrap
    on Aug 2, 2017

  4. refack commented on Aug 2, 2017

    @refack
    refack
    on Aug 2, 2017
    Contributor

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

  5. matthewloring commented on Aug 2, 2017

    @matthewloring
    matthewloring
    on Aug 2, 2017
    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.

  6. matthewloring commented on Aug 2, 2017

    @matthewloring
    matthewloring
    on Aug 2, 2017
    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).

  7. refack
    added
    flaky-testIssues and PRs involving tests that fail intermittently in CI.
    testIssues and PRs related to Node.js core tests and test infrastructure.
    on Aug 2, 2017

  8. refack commented on Aug 2, 2017

    @refack
    refack
    on Aug 2, 2017
    Contributor

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

  9. tniessen commented on Aug 2, 2017

    @tniessen
    tniessen
    on Aug 2, 2017
    Member

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

  10. addaleax
    added
    caresIssues and PRs related to the c-ares dependency or the cares_wrap binding.
    dnsIssues and PRs related to the dns subsystem.
    and removed
    async_wrap
    flaky-testIssues and PRs involving tests that fail intermittently in CI.
    testIssues and PRs related to Node.js core tests and test infrastructure.
    caresIssues and PRs related to the c-ares dependency or the cares_wrap binding.
    on Aug 4, 2017
  11. addaleax
    added a commit that references this issue on Aug 4, 2017

    src: properly manage timer in cares ChannelWrap

    3baafef

  12. addaleax commented on Aug 4, 2017

    @addaleax
    addaleax
    on Aug 4, 2017
    Member

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

  13. Trott commented on Aug 5, 2017

    @Trott
    Trott
    on Aug 5, 2017
    Member

    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)

  14. matthewloring commented on Aug 5, 2017

    @matthewloring
    matthewloring
    on Aug 5, 2017
    Author

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

  15. addaleax
    closed this as completedin 41a0dfcon Aug 7, 2017
  16. addaleax
    added a commit that references this issue on Aug 7, 2017

    src: properly manage timer in cares ChannelWrap

    3c6b5e5
  17. sjarmak
    added a commit that references this issue on Jul 27, 2026

    src: properly manage timer in cares ChannelWrap

    41a0dfc
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    dnsIssues and PRs related to the dns subsystem.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions