Repository navigation
[EventPipe] AV at EventPipeInternal_GetNextEvent #122630
Description
Activity
More investigation notes.
The Previous event (pInstance)
- ProviderID -> EventPipeProvider `Microsoft-Windows-DotNETRuntime: - EventID -> 0xa (10) "GCAllocationTick" - ThreadID -> 0x72 - TimeStamp 1876226655755078 (0x0006aa6b`0f559b46) - Payload [Freed] - PayloadLength 0x112 (264)The EventPipeSession
- session_start_time : 0n133953285480373022 - session_start_timestamp : 0n1873310975596637 - index : 1 - rundown_enabled : 0 - session_type : 1 ( EP_SESSION_TYPE_LISTENER ) - format : 1 ( EP_SERIALIZATION_FORMAT_NETTRACE_V4 ) - rundown_requested : 1 - paused : 0 - enable_stackwalk : 1 - started : 1The EventPipeBufferManager
- thread_session_state_list : 184 total, 5 with buffers Thread 0x72 : [Buffer A] (102400 bytes) [Buffer B] (204800 bytes) Thread 0x7C : [Buffer C] (102400 bytes) Thread 0x2d1e : [Buffer D] (102400 bytes) Thread 0x2dba : [Buffer E] (102400 bytes) Thread 0x2e73 : [Buffer F] (102400 bytes) - current_event : zero'd out - current_buffer : Buffer* of Thread 0x72 above - current_buffer_list : Thread 0x72's buffer_list - size_of_all_buffers : 0xaf000 ( - max_size_of_all_buffers : 0xa00000 - num_oversized_events_dropped : 0The EventPipeBuffer used to retrieve the EventPipeEventInstance
- creation_timestamp : 1876226656953887 - writer_thread : Thread 0x72 - buffer : 0x7fbefcd89000 - current : 0x7fbefcd89f78 - limit : 0x7fbefcda2000 - current_read_event : 0x7fbefcd89000 - prev_buffer : NULL - next_buffer : [Buffer B] - state : 1 (Read_Only) - event_sequence_number : 0x2edc13The entire memory region [buffer, limit) is all zero'd out, leading to the AV
current > bufferindicates that atleast one event was successfully written into the buffer
current_read_event == buffer+state == 1indicates that the buffer was converted to read_only
event_sequence_number == 0x2edc13indicates this thread had attempted to write 3070994 events before this buffer was allocated.
Hypothesis 1: A race led to a use-after-free on this EventPipeBuffer.
In this version of the runtime (.NET 8), buffers are only freed when:
- EventPipeBuffer allocation failed - The buffer wouldn't have been added to the buffer list ❌
- The buffer failed before being added to the buffer list - The buffer wouldn't be in the buffer list ❌
- The buffer was deallocated by the buffer manager - Regardless of call site, the buffer_manager should have reclaimed the buffer_size before freeing the buffer.
BufferManager->size_of_all_buffers 0xaf000 == 716800 == Buffer A (102400) + B (204800) + C (102400) + D (102400) + E (102400) + F (102400). Since the BufferManager's size of all buffers accounts for this buffer (A), it wasn't freed. ❌
0:224> !address 0x7fbefcd89000 Mapping file section regions... Mapping module regions... Mapping heap regions... Usage: <unknown> Base Address: 00007fbe`fcd89000 End Address: 00007fbe`fcda2000 Region Size: 00000000`00019000 ( 100.000 kB) State: 00001000 MEM_COMMIT Protect: 00000004 PAGE_READWRITE Type: 00020000 MEM_PRIVATE Allocation Base: 00007fbe`fcd89000 Allocation Protect: 00000004 PAGE_READWRITEThe EventPipeBuffer->buffer memory region was still committed.
It doesn't seem like EventPipe is aware that the buffer was freed.
Hypothesis 2: Some external process corrupted the memory region containing the EventPipeBuffer->buffer memory
Instrumentation like #118874 was added to help differentiate between an external cause corrupting memory vs the runtime self-inducing the memory corruption. i.e. if the runtime crashed with
EventPipeBufferGuardLevel=2, something external is corrupting memory.The user tried out the instrumentation and reported that there haven't been any crashes. Although this points towards the runtime itself freeing the memory and inducing the crash:
- This is the first time we are hearing of this particular crash despite EventListener having been introduced years ago (and supposedly many users have used EventListeners)
- The user reported the crashing behavior only occurs on machines that upgraded packages (Their other machines that didn't upgrade haven't experienced this crashing behavior)
- Reproducing the crash is unreliable: no steps to reproduce on other machines, crash occurs many hours while the app is running when millions of events have been written, unclear if there are other temporal/external factors at play.
Given the above, external factors causing the crash doesn't seem to be completely ruled out.
Hypothesis 3: The runtime itself is freeing the memory region containing the EventPipeBuffer->buffer memory
If
EventPipeBufferGuardLevel=2(and supposedly 1?) is truly preventing the crash, and counterarguments towards EventPipe freeing the memory are sound, then something outside of EventPipe is corrupting the memory.At the time of crash, the EventPipeBufferManager depicted 184 thread session states, 5 of which had events to be consumed.
In the dump, there were 231 threads with callstacks whose indices ranged from [0x0, 0xe6].Excluding the thread hitting the AV,
96 threads were gc_heap::bgc_thread_functionlibc_so!_nptl_death_event+0xda libc_so!pthread_cond_wait+0x1c0 libcoreclr!GCEvent::Impl::Wait+0xd2 [/__w/1/s/src/coreclr/gc/unix/events.cpp @ 179] libcoreclr!SVR::gc_heap::bgc_thread_function+0x68 [/__w/1/s/src/coreclr/gc/gc.cpp @ 39440] --------`-------- libcoreclr!<unnamed-namespace>::CreateSuspendableThread::$_0::operator()+0x63 [/__w/1/s/src/coreclr/vm/gcenv.ee.cpp @ 1440] libcoreclr!<unnamed-namespace>::CreateSuspendableThread::$_0::__invoke+0x74 [/__w/1/s/src/coreclr/inc/clrtypes.h @ 1420] libcoreclr!CorUnix::CPalThread::ThreadEntry+0x1fe [/__w/1/s/src/coreclr/pal/inc/pal.h @ 1763] libc_so!pthread_condattr_setpshared+0x4c2 libc_so!clone+0x44 0xffffffff`ffffffff96 threads were
gc_heap::gc_thread_functionlibc_so!_nptl_death_event+0xda libc_so!pthread_cond_wait+0x1c0 libcoreclr!GCEvent::Impl::Wait+0xd2 [/__w/1/s/src/coreclr/gc/unix/events.cpp @ 179] libcoreclr!SVR::gc_heap::gc_thread_function+0x8b [/__w/1/s/src/coreclr/gc/gc.cpp @ 7186] libcoreclr!SVR::gc_heap::gc_thread_stub+0x34 [/__w/1/s/src/coreclr/gc/gc.cpp @ 37386] --------`-------- libcoreclr!<unnamed-namespace>::CreateNonSuspendableThread::$_0::operator()+0x41 [/__w/1/s/src/coreclr/vm/gcenv.ee.cpp @ 1502] libcoreclr!<unnamed-namespace>::CreateNonSuspendableThread::$_0::__invoke+0x4e [/__w/1/s/src/coreclr/vm/gcenv.ee.cpp @ 1487] libcoreclr!CorUnix::CPalThread::ThreadEntry+0x1fe [/__w/1/s/src/coreclr/pal/inc/pal.h @ 1763] libc_so!pthread_condattr_setpshared+0x4c2 libc_so!clone+0x44 0xffffffff`ffffffff12 threads looked related to Kafka?
I'm currenlty not sure what else in the runtime could be corrupting the EventPipeBuffer->buffer memory region.
Hypothesis 4: Some other debugger/profiler is attached and overwriting memory
From the dump it doesn't look like a profiler is attached, and it didn't seem like the user was using a debugger.
12 threads looked related to Kafka?
What are the 3rd party nuget packages that are used by this app? The mysterious memory corruption like this are typically caused by buggy interop code in 3rd party packages.
Here is an example that I have investigated recently #122016 . (I am not saying that this example is related to this issue in any way. I am sharing it to demonstrate the weird failures that can be caused by buggy interop.)
Description
Some users that have been leveraging an EventListener to listen to basic GC events have been experiencing crashes due to an AV at
runtime/src/coreclr/vm/eventpipeinternal.cpp
Line 251 in b2969ed
Reproduction Steps
Unclear how to repro. The users were using .NET 8 and seem to just be using a standard EventListener to listen to events. The users mentioned that this crash seems to only occur in machines that have had their OS patched with kernel upgrades.
Expected behavior
EventPipe doesn't crash the runtime and doesn't return an invalid EventPipeEventInstance.
Actual behavior
Crashes due to AV
Regression?
No response
Known Workarounds
Disable EventListeners, use alternative APIs to grab the data held by the events, like GCMemoryInfo or other GC APIs for GC events.
Configuration
.NET 8, Linux-x64, kernel: 5.15.0-140-fips, AzureLinux3.0
Other information
While investigating the crash dump, we've observed that there is an EventPipeBuffer with it's buffer region all 0'd out, even though the EventPipeBuffer still needed its first EventPipeEventInstance read from its buffer region. (below
current_read_eventis atbuffer)This is unexpected, as buffer regions should only be cleared when
Moreover, the thread that was logging to this buffer had two buffers in its list, the readable
current_bufferabove, and another writable buffer whose event sequence number was0x2edc1c, indicating 9 events (0x2edc1c - 0x2edc13) being written incurrent_bufferabove. The writable buffer also had valid non-zeroed EventPipeEventInstances in its buffer region.With insufficient diagnostics to determine what exactly led to the EventPipeBuffer's buffer region being 0'd out, coupled with the dump suggesting a scenario that doesn't seem consistent with EventPipe logic, it's difficult to tell if this crash was really due to a race condition leading to use-after-free, or some external process corrupting memory.