corerun with DOTNET_EnableEventLog: "Heap contamination detected! "HeapFree was called on a heap other than the one that memory was allocated from."

[am11]

Based on current main (5bef921), build product and tests in Debug configuration on Ubuntu 18.04 x64:

./build.sh
./src/tests/build.sh -p:LibrariesConfiguration=Debug

Running a simple hello world app works:

cd artifacts/bin/testhost/net6.0-Linux-Debug-x64/shared/Microsoft.NETCore.App/6.0.0
corerun /tmp/helloworld.dll

running the same app with event log enabled fails an assertion:

DOTNET_EnableEventLog=1 corerun /tmp/helloworld.dll

Assert failure(PID 543 [0x0000021f], Thread: 543 [0x021f]): !"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: /runtime/src/coreclr/utilcode/clrhost_nodependencies.cpp Line: 296
    Image: /runtime/artifacts/bin/testhost/net6.0-Linux-Debug-x64/shared/Microsoft.NETCore.App/6.0.0/corerun

corehost, OTOH, has no issue with DOTNET_EnableEventLog=1 (or COMPlus_EnableEventLog=1).

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[am11]

cc @josalem, @janvorli
I found this when writing LTTng tests (wip branch: main...am11:feature/tracing/tests/lttng-events) and reduced it to a simple hello world. Setting DOTNET_EnableEventLog=1 on anything chokes corerun.

[josalem]

I'm not sure what would be different for LTTng between corehost and corerun. That seems odd. Is there any more to the stack when the assert is thrown? clrhost_nodependencies.cpp:296 is just ClrFree. I'll see if I can get an LTTng environment set up. If you can easily reproduce this though, it might be faster if you can run it under LLDB and get a bt at the assert.

(lldb corerun -- helloworld.dll -> (lldb) settings set target.env-vars DOTNET_EnableEventLog=1 -> etc.)

[am11]

This is only happening in debug build, I tested with release build and the test passed.

Here is the backtrace of helloworld.dll from lldb, when launching with corerun:

root@968b4a55cce2:/runtime/artifacts/tests/coreclr/Linux.x64.Debug/Tests/Core_Root# lldb -f ./corerun /tmp/helloworld/bin/Release/net6.0/helloworld.dll
(lldb) target create "./corerun"
Current executable set to './corerun' (x86_64).
(lldb) settings set -- target.run-args  "/tmp/helloworld/bin/Release/net6.0/helloworld.dll"
(lldb) settings set target.env-vars DOTNET_EnableEventLog=1
(lldb) r
Process 1756 launched: './corerun' (x86_64)
      
Assert failure(PID 1756 [0x000006dc], Thread: 1756 [0x06dc]): !"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: /runtime/src/coreclr/utilcode/clrhost_nodependencies.cpp Line: 296
    Image: /runtime/artifacts/tests/coreclr/Linux.x64.Debug/Tests/Core_Root/corerun

Process 1756 stopped
* thread #1, name = 'corerun', stop reason = signal SIGTRAP
    frame #0: 0x00007ffff6b52559 libcoreclr.so`DBG_DebugBreak at debugbreak.S:9
   6   	
   7   	LEAF_ENTRY DBG_DebugBreak, _TEXT
   8   	        int3
-> 9   	        ret
   10  	LEAF_END_MARKED DBG_DebugBreak, _TEXT
   11  	
(lldb) bt all
* thread #1, name = 'corerun', stop reason = signal SIGTRAP
  * frame #0: 0x00007ffff6b52559 libcoreclr.so`DBG_DebugBreak at debugbreak.S:9
    frame #1: 0x00007ffff6aa43cb libcoreclr.so`::DebugBreak() at debug.cpp:406
    frame #2: 0x00007ffff680e828 libcoreclr.so`::DbgAssertDialog(szFile="/runtime/src/coreclr/utilcode/clrhost_nodependencies.cpp", iLine=296, 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:697
    frame #3: 0x00007ffff67c13c2 libcoreclr.so`ClrFree(p=0x0000555555661c30) at clrhost_nodependencies.cpp:295
    frame #4: 0x00007ffff67c1175 libcoreclr.so`operator delete[](p=0x0000555555661c40) at clrhost_nodependencies.cpp:410
    frame #5: 0x00007ffff6bab80d libcoreclr.so`::FireEtXplatRuntimeInformationStart(ClrInstanceID=0, Sku=2, BclMajorVersion=6, BclMinorVersion=0, BclBuildNumber=0, BclQfeNumber=0, VMMajorVersion=42, VMMinorVersion=42, VMBuildNumber=42, VMQfeNumber=42424, StartupFlags=8388611, StartupMode='\0', CommandLine=u"", ComObjectGuid=0x00007ffff5fa9600, RuntimeDllPath=u"/runtime/artifacts/tests/coreclr/Linux.x64.Debug/Tests/Core_Root/libcoreclr.so") at eventprovdotnetruntime.cpp:4905
    frame #6: 0x00007ffff665ee35 libcoreclr.so`FireEtwRuntimeInformationStart(ClrInstanceID=0, Sku=2, BclMajorVersion=6, BclMinorVersion=0, BclBuildNumber=0, BclQfeNumber=0, VMMajorVersion=42, VMMinorVersion=42, VMBuildNumber=42, VMQfeNumber=42424, StartupFlags=8388611, StartupMode='\0', CommandLine=u"", ComObjectGuid=0x00007ffff5fa9600, RuntimeDllPath=u"/runtime/artifacts/tests/coreclr/Linux.x64.Debug/Tests/Core_Root/libcoreclr.so", ActivityId=0x0000000000000000, RelatedActivityId=0x0000000000000000) at clretwallmain.h:2811
    frame #7: 0x00007ffff664b58e libcoreclr.so`ETW::InfoLog::RuntimeInformation(type=0) at eventtrace.cpp:5111
    frame #8: 0x00007ffff6a73c1f libcoreclr.so`EEStartupHelper() at ceemain.cpp:767
    frame #9: 0x00007ffff6a75684 libcoreclr.so`EEStartup(this=0x00007fffffffda88, p=0x0000000000000000)::$_1::operator()(void*) const at ceemain.cpp:1153
    frame #10: 0x00007ffff6a72a5b libcoreclr.so`EEStartup() at ceemain.cpp:1155
    frame #11: 0x00007ffff6a72862 libcoreclr.so`EnsureEEStarted() at ceemain.cpp:321
    frame #12: 0x00007ffff6219bed libcoreclr.so`CorHost2::Start(this=0x0000555555634690) at corhost.cpp:101
    frame #13: 0x00007ffff6153006 libcoreclr.so`::coreclr_initialize(exePath="/runtime/artifacts/tests/coreclr/Linux.x64.Debug/Tests/Core_Root/corerun", appDomainFriendlyName="corerun", propertyCount=4, propertyKeys=0x000055555558a0c0, propertyValues=0x000055555558a140, hostHandle=0x0000555555566068, domainId=0x0000555555566070) at unixinterface.cpp:251
    frame #14: 0x000055555555f127 corerun`run(config=0x00007fffffffe460) at corerun.cpp:352
    frame #15: 0x000055555555c616 corerun`main(argc=2, argv=0x00007fffffffe5d8) at corerun.cpp:554
    frame #16: 0x00007ffff6ca1bf7 libc.so.6`__libc_start_main(main=(corerun`main at corerun.cpp:546), argc=2, argv=0x00007fffffffe5d8, init=<unavailable>, fini=<unavailable>, rtld_fini=<unavailable>, stack_end=0x00007fffffffe5c8) at libc-start.c:310
    frame #17: 0x000055555555b02a corerun`_start + 42
  thread #2, name = 'corerun-ust'
    frame #0: 0x00007ffff79c2657 libpthread.so.0`__libc_recvmsg + 71
    frame #1: 0x00007ffff5985c23 liblttng-ust.so.0`ustcomm_recv_unix_sock + 179
    frame #2: 0x00007ffff598b241 liblttng-ust.so.0`___lldb_unnamed_symbol62$$liblttng-ust.so.0 + 2241
    frame #3: 0x00007ffff79b76db libpthread.so.0`start_thread + 219
    frame #4: 0x00007ffff6da171f libc.so.6`__GI___clone at clone.S:95
  thread #3, name = 'corerun-ust'
    frame #0: 0x00007ffff6d9b639 libc.so.6`syscall at syscall.S:38
    frame #1: 0x00007ffff598abd3 liblttng-ust.so.0`___lldb_unnamed_symbol62$$liblttng-ust.so.0 + 595
    frame #2: 0x00007ffff79b76db libpthread.so.0`start_thread + 219
    frame #3: 0x00007ffff6da171f libc.so.6`__GI___clone at clone.S:95
  thread #4, name = 'corerun'
    frame #0: 0x00007ffff6d94cb9 libc.so.6`__GI___poll(fds=0x00007fffed55ca20, nfds=1, timeout=-1) at poll.c:29
    frame #1: 0x00007ffff6b30459 libcoreclr.so`CorUnix::CPalSynchronizationManager::ReadBytesFromProcessPipe(this=0x0000555555638900, iTimeout=-1, pRecvBuf="", iBytes=1) at synchmanager.cpp:2233
    frame #2: 0x00007ffff6b2f618 libcoreclr.so`CorUnix::CPalSynchronizationManager::ReadCmdFromProcessPipe(this=0x0000555555638900, iPollTimeout=-1, pswcWorkerCmd=0x00007fffed55cde4, pshridMarshaledData=0x00007fffed55cdd8, pdwData=0x00007fffed55cdd4) at synchmanager.cpp:2011
    frame #3: 0x00007ffff6b2e1c6 libcoreclr.so`CorUnix::CPalSynchronizationManager::WorkerThread(pArg=0x0000555555638900) at synchmanager.cpp:1714
    frame #4: 0x00007ffff6b4d315 libcoreclr.so`CorUnix::CPalThread::ThreadEntry(pvParam=0x0000555555639620) at thread.cpp:1862
    frame #5: 0x00007ffff79b76db libpthread.so.0`start_thread + 219
    frame #6: 0x00007ffff6da171f libc.so.6`__GI___clone at clone.S:95
  thread #5, name = 'corerun'
    frame #0: 0x00007ffff6d94cb9 libc.so.6`__GI___poll(fds=0x00007fff70008ee0, nfds=1, timeout=-1) at poll.c:29
    frame #1: 0x00007ffff689db13 libcoreclr.so`ipc_poll_fds(fds=0x00007fff70008ee0, nfds=1, timeout=4294967295) at ds-ipc-pal-socket.c:485
    frame #2: 0x00007ffff689d904 libcoreclr.so`ds_ipc_poll(poll_handles_data=0x00007fffecd5bb60, poll_handles_data_len=1, timeout_ms=4294967295, callback=(libcoreclr.so`server_warning_callback(char const*, unsigned int) at ds-server.c:110))(char const*, unsigned int)) at ds-ipc-pal-socket.c:1082
    frame #3: 0x00007ffff6a5177b libcoreclr.so`ds_ipc_stream_factory_get_next_available_stream(callback=(libcoreclr.so`server_warning_callback(char const*, unsigned int) at ds-server.c:110))(char const*, unsigned int)) at ds-ipc.c:395
    frame #4: 0x00007ffff6a4eba7 libcoreclr.so`server_thread(data=0x0000000000000000) at ds-server.c:127
    frame #5: 0x00007ffff6b4d315 libcoreclr.so`CorUnix::CPalThread::ThreadEntry(pvParam=0x0000555555657640) at thread.cpp:1862
    frame #6: 0x00007ffff79b76db libpthread.so.0`start_thread + 219
    frame #7: 0x00007ffff6da171f libc.so.6`__GI___clone at clone.S:95

and without settings set target.env-vars DOTNET_EnableEventLog=1, it works fine:

(lldb) r
Process 1576 launched: './corerun' (x86_64)
Hello World!
Process 1576 exited with status = 0 (0x00000000) 

helloworld.dll was generated with:

$ /runtime/.dotnet/dotnet  new console -o /tmp/helloworld
$ cd /tmp/helloworld
$ /runtime/.dotnet/dotnet build -c Release

[janvorli]

I wonder if it is yet another case of a mismatch between standard new operator and our overriden delete[], like we've seen in mscordaccore. Isn't this code by any chance using the STL? That would be bad.

[janvorli]

Ok, seems no STL is there. But I can see the problem. The ResizeBuffer is in PAL and as such uses standard new operator. The code that asserts is built on top of PAL though (like runtime) and so it cannot use the standard delete operator and uses our override instead.
The reason why it works in release builds is that we add extra information into the memory around the allocation only in non-release builds. So for release builds, our ClrFree becomes just free and it works.

[janvorli]

It seems the right fix would be to implement a function to delete the buffer in the eventproviderhelpers.cpp like the ResizeBuffer and call it instead of the delete. That way both new and delete would be guaranteed to be compatible.

Tagging subscribers to this area: @tommcdon
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Based on current main (5bef921), build product and tests in Debug configuration on Ubuntu 18.04 x64:

./build.sh
./src/tests/build.sh -p:LibrariesConfiguration=Debug

Running a simple hello world app works:

cd artifacts/bin/testhost/net6.0-Linux-Debug-x64/shared/Microsoft.NETCore.App/6.0.0
corerun /tmp/helloworld.dll

running the same app with event log enabled fails an assertion:

DOTNET_EnableEventLog=1 corerun /tmp/helloworld.dll

Assert failure(PID 543 [0x0000021f], Thread: 543 [0x021f]): !"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: /runtime/src/coreclr/utilcode/clrhost_nodependencies.cpp Line: 296
    Image: /runtime/artifacts/bin/testhost/net6.0-Linux-Debug-x64/shared/Microsoft.NETCore.App/6.0.0/corerun

corehost, OTOH, has no issue with DOTNET_EnableEventLog=1 (or COMPlus_EnableEventLog=1).

Author:	am11
Assignees:	-
Labels:	area-Diagnostics-coreclr, untriaged
Milestone:	-

[josalem]

To make sure we're on the same page, this is the ResizeBuffer you're talking about?

runtime/src/coreclr/pal/src/eventprovider/lttngprovider/eventproviderhelpers.cpp

Lines 14 to 39 in 1fb151f

	bool ResizeBuffer(char *&buffer, size_t& size, size_t currLen, size_t newSize, bool &fixedBuffer)
	{
	newSize = (size_t)(newSize * 1.5);
	_ASSERTE(newSize > size); // check for overflow
	if (newSize < 32)
	newSize = 32;
	// We can't use coreclr includes here so we use std::nothrow
	// rather than the coreclr version
	char *newBuffer = new (std::nothrow) char[newSize];
	if (newBuffer == NULL)
	return false;
	memcpy(newBuffer, buffer, currLen);
	if (!fixedBuffer)
	delete[] buffer;
	buffer = newBuffer;
	size = newSize;
	fixedBuffer = false;
	return true;
	}

Looks like EventPipe got around this by having ResizeBuffer re-defined on top of the PAL:

runtime/src/coreclr/scripts/genEventPipe.py

Lines 419 to 453 in 1fb151f

	#include "common.h"
	#include <stdlib.h>
	#include <string.h>
	#ifndef TARGET_UNIX
	#include <windef.h>
	#include <crtdbg.h>
	#else
	#include "pal.h"
	#endif //TARGET_UNIX
	bool ResizeBuffer(BYTE *&buffer, size_t& size, size_t currLen, size_t newSize, bool &fixedBuffer)
	{
	newSize = (size_t)(newSize * 1.5);
	_ASSERTE(newSize > size); // check for overflow
	if (newSize < 32)
	newSize = 32;
	BYTE *newBuffer = new (nothrow) BYTE[newSize];
	if (newBuffer == NULL)
	return false;
	memcpy(newBuffer, buffer, currLen);
	if (!fixedBuffer)
	delete[] buffer;
	buffer = newBuffer;
	size = newSize;
	fixedBuffer = false;
	return true;
	}

[janvorli]

Yes, I was talking about the one in the eventproviderhelpers.cpp. If you added a DeleteBuffer function there and called it instead of using the delete in the generated eventprovdotnetruntime.cpp, it would fix the issue. The way eventpipe did that would work as well, but it seems that the way I've suggested is kind of cleaner.

[josalem]

Thanks for the triage @janvorli. @am11 if you aren't planning to include that change in your PR, I'll go ahead and make it.