Runtime: [Linux][RHEL] Heap contamination detected! HeapFree was called on a heap other than the one that memory was allocated from

Created on 21 Nov 2019 · 28Comments · Source: dotnet/runtime

https://helix.dot.net/api/2019-06-17/jobs/01c8c73c-d102-4ec4-8680-1e9dd63d454b/workitems/JIT.Stress/console

https://dev.azure.com/dnceng/public/_build/results?buildId=433392&view=logs

JIT/Stress/ABI/tailcalls_do/tailcalls_do.sh [FAIL]

      Assert failure(PID 24244 [0x00005eb4], Thread: 24253 [0x5ebd]): !"Heap contamination detected! HeapFree was called on a heap other than the one that memory was allocated from.\n" "Possible cause: you used new (executable) to allocate the memory, but didn't use DeleteExecutable() to free it."
          File: /__w/2/s/src/coreclr/src/vm/hosting.cpp Line: 268
          Image: /home/helixbot/work/01c8c73c-d102-4ec4-8680-1e9dd63d454b/Payload/corerun

      /home/helixbot/work/01c8c73c-d102-4ec4-8680-1e9dd63d454b/Work/8543e0ef-3fed-493d-b02b-356fdd033e54/Exec/JIT/Stress/ABI/tailcalls_do/tailcalls_do.sh: line 294: 24244 Aborted                 $LAUNCHER $ExePath "${CLRTestExecutionArguments[@]}"

      Return code:      1
      Raw output file:      /home/helixbot/work/01c8c73c-d102-4ec4-8680-1e9dd63d454b/Work/8543e0ef-3fed-493d-b02b-356fdd033e54/Exec/JIT/Stress/Reports/JIT.Stress/ABI/tailcalls_do/tailcalls_do.output.txt
      Raw output:
      BEGIN EXECUTION
      /home/helixbot/work/01c8c73c-d102-4ec4-8680-1e9dd63d454b/Payload/corerun tailcalls_do.dll '--tailcalls' '--num-calls' '1000' '--no-ctrlc-summary'
      Stressing tailcalls
      OSVersion: Unix 2.6.32.754
      OSArchitecture: X64
      ProcessArchitecture: X64
      Selecting SysV ABI
      50 callers done (49 successful tailcalls tested)
      100 callers done (98 successful tailcalls tested)
      150 callers done (146 successful tailcalls tested)
      200 callers done (194 successful tailcalls tested)
      250 callers done (244 successful tailcalls tested)
      300 callers done (294 successful tailcalls tested)
      350 callers done (339 successful tailcalls tested)
      400 callers done (388 successful tailcalls tested)
      450 callers done (434 successful tailcalls tested)
      500 callers done (483 successful tailcalls tested)
      550 callers done (532 successful tailcalls tested)
      600 callers done (581 successful tailcalls tested)
      650 callers done (631 successful tailcalls tested)
      700 callers done (681 successful tailcalls tested)
      750 callers done (730 successful tailcalls tested)
      800 callers done (779 successful tailcalls tested)
      850 callers done (828 successful tailcalls tested)
      900 callers done (878 successful tailcalls tested)
      950 callers done (927 successful tailcalls tested)
      1000 callers done (975 successful tailcalls tested)
      975 tailcalls tested
      24 rejected tailcalls. Breakdown:
      [100.00%]: Not enough incoming arg space
      Expected: 100
      Actual: 134
      END EXECUTION - FAILED

EventPipe area-Tracing-coreclr disabled-test

Source

jashook

All 28 comments

@janvorli you may find this interesting. Unfortunately to disable this test on this one platform, we have to disable it for all unix platforms.

jashook on 21 Nov 2019

@jashook please apply the "disabled-test" label if you disabled tests with a tracking issue.

ViktorHofer on 21 Nov 2019

👍1

Looks like this failure is much more systemic then a set of tests. This seems to occur on many different tests. Changing title.

jashook on 21 Nov 2019

@janvorli do you have a suggestion on routing?

jashook on 21 Nov 2019

@jashook did it start to happen after moving to the runtime repo? And if so, any idea what have changed in the build?

janvorli on 21 Nov 2019

It looks like we weren't testing rhel6 before we moved, but we are now.

jashook on 21 Nov 2019

I will need to investigate that, with so much changing it may be hard to find out why

jashook on 21 Nov 2019

Ok, let me take a look into the issue.

janvorli on 21 Nov 2019

This issue is a dup of https://github.com/dotnet/coreclr/issues/23580

jashook on 21 Nov 2019

It looks like this was re-enabled when the issue looked like it was closed. Looks like the root cause was not fixed.

jashook on 21 Nov 2019

Looking back disabling this test leg led to us not running rhel 6 testing and missing what seems like a product issue.

jashook on 21 Nov 2019

To avoid the latter happening I think we should alter policy and allow these legs to run red until fixed /cc @echesakovMSFT @tommcdon

jashook on 21 Nov 2019

Decided to disable the testing again. Please do not close this issue without re-enabling RHEL 6 testing.

jashook on 23 Nov 2019

I've tried to give it a quick look and got some details that may lead us to figuring out what's causing it. I was able to repro it with debug build of coreclr using our centos 6 docker image. Here is the call stack at the time of the failure:

  * frame #0: 0x00007ffff6629d19 libcoreclr.so`DBG_DebugBreak at debugbreak.S:10
    frame #1: 0x00007ffff6578a0b libcoreclr.so`::DebugBreak() at debug.cpp:405:9
    frame #2: 0x00007ffff5d545f8 libcoreclr.so`::DbgAssertDialog(szFile="/root/coreclr/src/vm/hosting.cpp", iLine=268, szExpr="!\"Heap contamination detected! HeapFree was called on a heap other than the one that memory was allocated from.\\n\" \"Possible cause: you used new (executable) to allocate the memory, but didn't use DeleteExecutable() to free it.\"") at debug.cpp:710:13
    frame #3: 0x00007ffff5fc9cd9 libcoreclr.so`EEHeapFree(hHeap=0x0000000001020304, dwFlags=0, lpMem=0x00005555559d07a0) at hosting.cpp:267:17
    frame #4: 0x00007ffff5fc9d70 libcoreclr.so`EEHeapFreeInProcessHeap(dwFlags=0, lpMem=0x00005555559d07b0) at hosting.cpp:299:12
    frame #5: 0x00007ffff5d2c91a libcoreclr.so`ClrFreeInProcessHeap(dwFlags=0, lpMem=0x00005555559d07b0) at clrhost.h:216:12
    frame #6: 0x00007ffff5d2ba82 libcoreclr.so`operator delete(p=0x00005555559d07b0) at clrhost_nodependencies.cpp:434:9
    frame #7: 0x00007ffff66fd4c2 libcoreclr.so`(anonymous namespace)::run(void*) + 34
    frame #8: 0x00007ffff6ebca02 libc.so.6`__GI_exit + 226
    frame #9: 0x00007ffff6ea5d27 libc.so.6`__libc_start_main + 263
    frame #10: 0x0000555555557975 corerun`_start + 41
    frame #11: 0x0000555555557975 corerun`_start + 41

Since the issue happens in a call chain of __GI_exit, it means the operator delete is called from a destructor of a static c++ object (or maybe a thread static one?).
I don't know what the (anonymous namespace)::run(void*) is, probably some compiler generate thing. But looking at the disass of the function:

    0x7ffff66fd4a5 <+5>:  pushq  %rbp
    0x7ffff66fd4a6 <+6>:  pushq  %rbx
    0x7ffff66fd4a7 <+7>:  movq   %rdi, %rbx
    0x7ffff66fd4aa <+10>: subq   $0x8, %rsp
    0x7ffff66fd4ae <+14>: nop
    0x7ffff66fd4b0 <+16>: movq   0x8(%rbx), %rdi
    0x7ffff66fd4b4 <+20>: callq  *(%rbx)
    0x7ffff66fd4b6 <+22>: movq   0x10(%rbx), %rbp
    0x7ffff66fd4ba <+26>: movq   %rbx, %rdi
    0x7ffff66fd4bd <+29>: callq  0x7ffff5d2ba60            ; operator delete at clrhost_nodependencies.cpp:428

I can see that before calling the operator delete, it has called a function whose address is stored in memory at an address stored in RBX. Dumping that address:

 x/gx $rbx
0x5555559d07b0: 0x00007ffff5faab50

And disassembling the code there:

(lldb) disass -s 0x00007ffff5faab50
libcoreclr.so`Wrapper<EventPipeThread*, &(AcquireEventPipeThreadRef(EventPipeThread*)), &(ReleaseEventPipeThreadRef(EventPipeThread*)), 0ul, &(int CompareDefault<EventPipeThread*>(EventPipeThread*, EventPipeThread*)), true>::~Wrapper:
    0x7ffff5faab50 <+0>:  pushq  %rbp
    0x7ffff5faab51 <+1>:  movq   %rsp, %rbp
    0x7ffff5faab54 <+4>:  subq   $0x10, %rsp
    0x7ffff5faab58 <+8>:  movq   %rdi, -0x8(%rbp)
    0x7ffff5faab5c <+12>: movq   -0x8(%rbp), %rax
    0x7ffff5faab60 <+16>: movq   %rax, %rdi
    0x7ffff5faab63 <+19>: callq  0x7ffff5faac90            ; BaseWrapper<EventPipeThread*, FunctionBase<EventPipeThread*, &(AcquireEventPipeThreadRef(EventPipeThread*)), &(ReleaseEventPipeThreadRef(EventPipeThread*))>, 0ul, &(int CompareDefault<EventPipeThread*>(EventPipeThread*, EventPipeThread*))>::~BaseWrapper at holder.h:473
    0x7ffff5faab68 <+24>: addq   $0x10, %rsp
    0x7ffff5faab6c <+28>: popq   %rbp
    0x7ffff5faab6d <+29>: retq

It is obvious that the deletion stems from the Wrapper<EventPipeThread*, &(AcquireEventPipeThreadRef(EventPipeThread*)), &(ReleaseEventPipeThreadRef(EventPipeThread*)), 0ul, &(int CompareDefault<EventPipeThread*>(EventPipeThread*, EventPipeThread*)), true>::~Wrapper().
The type is typedefed as EventPipeThreadHolder.

janvorli on 25 Nov 2019

I've tried to set a breakpoint at BaseWrapper<EventPipeThread*, FunctionBase<EventPipeThread*, &(AcquireEventPipeThreadRef(EventPipeThread*)), &(ReleaseEventPipeThreadRef(EventPipeThread*))>, 0ul, &(int CompareDefault<EventPipeThread*>(EventPipeThread*, EventPipeThread*))>::BaseWrapper (I used the BaseWrapper - the base class as the Wrapper itself doesn't seem to have a constructor visible to the debugger) and also at the destructor.
Running the test, I've found that the instance that is destroyed right before calling the asserting operator delete is created here:

  * frame #0: 0x00007ffff5faaf27 libcoreclr.so`BaseWrapper<EventPipeThread*, FunctionBase<EventPipeThread*, &(AcquireEventPipeThreadRef(EventPipeThread*)), &(ReleaseEventPipeThreadRef(EventPipeThread*))>, 0ul, &(int CompareDefault<EventPipeThread*>(EventPipeThread*, EventPipeThread*))>::BaseWrapper(this=0x0000555555768858, value=0x0000000000000000, take=YES) at holder.h:585:17
    frame #1: 0x00007ffff5faabc1 libcoreclr.so`Wrapper<EventPipeThread*, &(AcquireEventPipeThreadRef(EventPipeThread*)), &(ReleaseEventPipeThreadRef(EventPipeThread*)), 0ul, &(int CompareDefault<EventPipeThread*>(EventPipeThread*, EventPipeThread*)), true>::Wrapper(this=0x0000555555768858) at holder.h:792:11
    frame #2: 0x00007ffff5d22db0 libcoreclr.so`::__cxx_global_var_init() at eventpipethread.cpp:110:40
    frame #3: 0x00007ffff5faab19 libcoreclr.so`__tls_init at eventpipethread.cpp:0
    frame #4: 0x00007ffff5faa3f9 libcoreclr.so`thread-local wrapper routine for EventPipeThread::gCurrentEventPipeThreadHolder at eventpipethread.cpp:147:12
    frame #5: 0x00007ffff5faa42d libcoreclr.so`EventPipeThread::GetOrCreate() at eventpipethread.cpp:160:9
    frame #6: 0x00007ffff5f9e994 libcoreclr.so`EventPipe::WriteEventInternal(pThread=0x00005555557dc730, event=0x00005555559cacf0, payload=0x00007fffffffc4e8, pActivityId=0x00005555557dd54c, pRelatedActivityId=0x0000000000000000, pEventThread=0x0000000000000000, pStack=0x0000000000000000) at eventpipe.cpp:594:47
    frame #7: 0x00007ffff5f9e838 libcoreclr.so`EventPipe::WriteEventInternal(event=0x00005555559cacf0, payload=0x00007fffffffc4e8, pActivityId=0x00005555557dd54c, pRelatedActivityId=0x0000000000000000) at eventpipe.cpp:565:5
    frame #8: 0x00007ffff5f9e8b4 libcoreclr.so`EventPipe::WriteEvent(event=0x00005555559cacf0, pEventData=0x00007fffffffc820, eventDataCount=4, pActivityId=0x0000000000000000, pRelatedActivityId=0x0000000000000000) at eventpipe.cpp:536:5
    frame #9: 0x00007ffff6262ba3 libcoreclr.so`EventPipeInternal::WriteEventData(eventHandle=93824996912368, eventID=1, pEventData=0x00007fffffffc820, eventDataCount=4, pActivityId=0x0000000000000000, pRelatedActivityId=0x0000000000000000) at eventpipeinternal.cpp:250:5
    frame #10: 0x00007fff7c573d3b
    frame #11: 0x00007fff7c94b020
    frame #12: 0x00007fff7c961b9c
    frame #13: 0x00007fff7c968c1f
    frame #14: 0x00007fff7c96687b
    frame #15: 0x00007fff7cf3f770
    frame #16: 0x00007fff7cf28b5a
    frame #17: 0x00007ffff613d413 libcoreclr.so`CallDescrWorkerInternal at unixasmmacrosamd64.inc:866
    frame #18: 0x00007ffff5f42f52 libcoreclr.so`CallDescrWorkerWithHandler(pCallDescrData=0x00007fffffffd4c8, fCriticalCall=NO) at callhelpers.cpp:70:5
    frame #19: 0x00007ffff5f43ccc libcoreclr.so`MethodDescCallSite::CallTargetWorker(this=0x00007fffffffd650, pArguments=0x00007fffffffd5f0, pReturnValue=0x00007fffffffd548, cbReturnValue=8) at callhelpers.cpp:546:9
    frame #20: 0x00007ffff5ee26af libcoreclr.so`MethodDescCallSite::Call_RetArgSlot(this=0x00007fffffffd650, pArguments=0x00007fffffffd5f0) at callhelpers.h:459:9
    frame #21: 0x00007ffff6168b01 libcoreclr.so`RunMainInternal(pParam=0x00007fffffffd8c0) at assembly.cpp:1493:48
    frame #22: 0x00007ffff6168809 libcoreclr.so`RunMain(this=0x00007fffffffd7c8, pParam=0x00007fffffffd8c0)::$_1::operator()(Param*) const::'lambda'(Param*)::operator()(Param*) const at assembly.cpp:1561:9
    frame #23: 0x00007ffff6166069 libcoreclr.so`RunMain(this=0x00007fffffffd8b0, __EXparam=0x00007fffffffd8c0)::$_1::operator()(Param*) const at assembly.cpp:1563:5
    frame #24: 0x00007ffff6165e89 libcoreclr.so`RunMain(pFD=0x00007fff7d131f28, numSkipArgs=1, piRetVal=0x00007fffffffd9bc, stringArgs=0x00007fffffffde90) at assembly.cpp:1563:5
    frame #25: 0x00007ffff6166312 libcoreclr.so`Assembly::ExecuteMainMethod(this=0x00005555558b6c90, stringArgs=0x00007fffffffde90, waitForOtherThreads=YES) at assembly.cpp:1673:18
    frame #26: 0x00007ffff5d8bc0b libcoreclr.so`CorHost2::ExecuteAssembly(this=0x0000555555775460, dwAppDomainId=1, pwzAssemblyPath=u"/root/coreclr/bin/tests/Linux.x64.Debug/tracing/eventsource/eventsourcetrace/eventsourcetrace/eventsourcetrace.dll", argc=0, argv=0x0000000000000000, pReturnValue=0x00007fffffffe13c) at corhost.cpp:460:39
    frame #27: 0x00007ffff5d2a4ea libcoreclr.so`::coreclr_execute_assembly(hostHandle=0x0000555555775460, domainId=1, argc=0, argv=0x0000000000000000, managedAssemblyPath="/root/coreclr/bin/tests/Linux.x64.Debug/tracing/eventsource/eventsourcetrace/eventsourcetrace/eventsourcetrace.dll", exitCode=0x00007fffffffe13c) at unixinterface.cpp:407:24
    frame #28: 0x0000555555558f7f corerun`ExecuteManagedAssembly(currentExeAbsolutePath="/root/coreclr/bin/tests/Linux.x64.Debug/Tests/Core_Root/corerun", clrFilesAbsolutePath="/root/coreclr/bin/tests/Linux.x64.Debug/Tests/Core_Root", managedAssemblyAbsolutePath="/root/coreclr/bin/tests/Linux.x64.Debug/tracing/eventsource/eventsourcetrace/eventsourcetrace/eventsourcetrace.dll", managedAssemblyArgc=0, managedAssemblyArgv=0x0000000000000000) at coreruncommon.cpp:476:22
    frame #29: 0x0000555555557f8c corerun`main(argc=2, argv=0x00007fffffffe3c8) at corerun.cpp:149:20
    frame #30: 0x00007ffff6ea5d20 libc.so.6`__libc_start_main + 256
    frame #31: 0x0000555555557975 corerun`_start + 41
    frame #32: 0x0000555555557975 corerun`_start + 41

However, it is important to say that the address passed to the operator delete is not address of the Wrapper's storage. It is an address of a block that is created by __cxa_thread_atexit which is called by the __cxx_global_var_init and that contains pointer to the Wrapper object and its destructor method.
It looks like for some reason, this block is allocated from standard C++ heap (using default new operator), but for destruction, our implementation operator delete that expects the address to be allocated from our heap is being called. Since this test is failing only on RHEL 6, it seems that the old version of glibc is likely somehow responsible for the issue.

To fix the problem it seems that somehow not using the holder for the pointer held in the gCurrentEventPipeThreadHolder could help and would also give us control over the time the underlying object is destroyed. The way it is now, for the main thread of the application, the destruction happens after the "main" of our host app has exited. So it is similar to the various "atexit" cases that we've eliminated in the past because they were causing various problems.

janvorli on 25 Nov 2019

The easiest way actually seems to be to put the gCurrentEventPipeThreadHolder as a member to the Thread class.

janvorli on 25 Nov 2019

cc: @jorive, @tommcdon

janvorli on 25 Nov 2019

@josalem can you take a look?

tommcdon on 26 Nov 2019

👀1

The easiest way actually seems to be to put the gCurrentEventPipeThreadHolder as a member to the Thread class.

Unfortunately this thread-static data was specifically moved off of the Thread class because it needs to be used for GC events and the GC threads don't have a Thread object assigned to them. @josalem is researching if we have other options.

noahfalk on 27 Nov 2019

@noahfalk got it. Then it seems we can just change the gCurrentEventPipeThreadHolder to be just a pointer instead of the wrapper and destroy the underlying object in Thread destructor. For GC threads, we don't need to destroy it as they never die.

janvorli on 27 Nov 2019

I was able to repro this in a RHEL6 vm, but I haven't started work on a change to bypass the bad behavior. I am curious what the priority/scope of a "fix" for this would look like in light of #423. Is this high enough priority to "fix" for 3.0/3.1? Is this worth "fixing" in 5.0 if we are dropping support for this OS version in 5.0?

josalem on 3 Dec 2019

I would like to fix that even in 5.0 just to get rid of the last place where a destructor is called at process exit.

janvorli on 3 Dec 2019

Okay, let me add this to the backlog.

josalem on 3 Dec 2019

The EventPipeThread has an array of EventPipeSessionStates on it. Each of those have an EventPipeThreadHolder field on them which creates a copy of the Wrapper and acts as a hard reference to the underlying memory. This means that the original Wrapper does get deleted on physical thread exit, but its destructor just decrements the internal ref count of the EventPipeThread object. That memory won't be deleted until its ref count hits zero (it calls delete this on itself), which won't happen until the EventPipeBufferManager calls DeallocatedBuffers when all EventPipe sessions have closed.

Quoting my comments on the PR I opened and then closed.

The issue here seems to be one with the c++ runtime version in RHEL6 and not an issue with the code itself. I'm going to do a little more investigation into what is specifically causing the error, but I'm inclined to believe this is an issue with the c++ runtime incorrectly deleting the thread_local Wrapper<...> member on EventPipeThread. EventPipeThread has acquire and release semantics where an internal ref count is incremented and decremented. When that count hits 0, it calls delete this on itself. The main thread will keep a hard reference to the EventPipeThread via the thread_local wrapper, which is how we get into the at_exit delete case.

I see this as a couple different issues of varying severity discovered here:

RHEL6 (glibc 2.12) has a bug that somehow results in calling the wrong delete operator being called at_exit on the Wrapper<...>

I don't see this as very high priority as we have already said we're dropping support for this version

There is a _partial_ leak where EventPipeThread objects remain alive after their physical thread dies until _all_ EventPipe sessions are closed

The scope of this leak isn't huge (~256 B per object * number of threads created while sessions are active), but the integral for a very long-lived application that gets traced for the life of the process can get large.

The main thread's Wrapper<...> --> EventPipeThread will stay alive until the death of the physical thread since the Wrapper<...> is a hard reference.

This is the true at_exit issue that Jan pointed out above. I think a fix here, might be to modify the wrapper to be a weak reference semantic, so that the EventPipeThread can get deleted when everything else is finished with it.

josalem on 14 Dec 2019

👍1

@josalem close?

tommcdon on 29 Jul 2020

I'm inclined to punt this to 6.0. I'm not sure it's worth the risk to mess with this infrastructure this close to 5.0.

josalem on 30 Jul 2020

If we think issues are puntable then maybe it should be closed as "Won't Fix"? Did any customer care that we left this unfixed for a year? Would we still support RHEL6 in .NET 6?

noahfalk on 30 Jul 2020

👍1

I suggest closing this bug. This is not a supported platform for this release. When the bug was opened things were not as concrete.

@janvorli do you object?

jashook on 30 Jul 2020

👍1

Was this page helpful?

0 / 5 - 0 ratings