AccessViolation when calling rejitted method

[kevingosse]

Description

We have noticed crashes in our CI when running tests with our profiler. We've seen crashes with .NET 6 on x86 and ARM64, but other runtime versions or platforms could also be impacted. The process crashes with an AccessViolation/Segfault during shutdown.

I managed to capture a memory dump and found a few things:

• The shutdown is initiated by a call to Environment.Exit(0)
• During shutdown, the System.AppContext::OnProcessExit event is raised, and our event handler tries to send stuff via HTTP
• System.Net.Http.HttpClientHandler.SendAsync tries to call System.Net.Http.SocketsHttpHandler.SendAsync
• During the method call, the execution jumps to address 0x0 and causes the crash

The method call in HttpClientHandler.SendAsync looks like:

0ff772e3 8b4da4          mov     ecx,dword ptr [ebp-5Ch]
0ff772e6 8b55e0          mov     edx,dword ptr [ebp-20h]
0ff772e9 8b45a4          mov     eax,dword ptr [ebp-5Ch]
0ff772ec 8b00            mov     eax,dword ptr [eax]
0ff772ee 8b4028          mov     eax,dword ptr [eax+28h]
0ff772f1 ff5014          call    dword ptr [eax+14h]

As far as I can tell, mov eax,dword ptr [ebp-5Ch] moves the address of the HttpClientHandler to eax. Then mov eax,dword ptr [eax] reads the method table, and the next two instructions fetch the destination of the call (I'm not familiar with the layout of the method table).

call dword ptr [eax+14h] ends up calling the address 0ff7c990 which is just a jump:

0:011> !U 0ff7c990
Unmanaged code
0ff7c990 e94b050100      jmp     0ff8cee0

Then 0ff8cee0 contains the tiered jit stub:

0:011> !U 0ff8cee0
Unmanaged code
0ff8cee0 b884bd3d0f      mov     eax,0F3DBD84h
0ff8cee5 66ff08          dec     word ptr [eax]
0ff8cee8 0f85123107f0    jne     00000000
0ff8ceee e8fff36540      call    coreclr!OnCallCountThresholdReachedStub (505ec2f2)

Notice the jne 00000000, which causes the access violation.

A few things to note:

• We rejitted HttpClientHandler.SendAsync:

0:011> !DumpMD /d 0d15a570
Method Name:          System.Net.Http.HttpClientHandler.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
Class:                0d168388
MethodTable:          0d15a67c
mdToken:              0600029D
Module:               0d156d20
IsJitted:             yes
Current CodeAddr:     0ff77258
Version History:
  ILCodeVersion:      0CDD5E30
  ReJIT ID:           4
  IL Addr:            0ff57550
     CodeAddr:           0ff77258  (QuickJitted)
     NativeCodeVersion:  0CE8F538
  ILCodeVersion:      00000000
  ReJIT ID:           0
  IL Addr:            7819b150
     CodeAddr:           78126a30  (ReadyToRun)
     NativeCodeVersion:  00000000

• We rejitted SocketsHttpHandler.SendAsync:

0:011> !DumpMD /d 0d15d558
Method Name:          System.Net.Http.SocketsHttpHandler.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
Class:                0d16a568
MethodTable:          0d15d58c
mdToken:              0600085A
Module:               0d156d20
IsJitted:             yes
Current CodeAddr:     0ffb0010
Version History:
  ILCodeVersion:      0CDD5890
  ReJIT ID:           6
  IL Addr:            0ff5be48
     CodeAddr:           0ffb0010  (QuickJitted)
     NativeCodeVersion:  0CE90488
  ILCodeVersion:      00000000
  ReJIT ID:           0
  IL Addr:            781c3258
     CodeAddr:           7816a5b0  (ReadyToRun)
     NativeCodeVersion:  00000000

I'm not sure where to go from there. If I add a Thread.Sleep at the beginning of the test then I can't reproduce the issue anymore, so the timing seems important. It's possible that we have a bug in our profiler and we don't handle rejitting correctly, but even in that case I feel like the JIT should never end up writing an empty address in the stub.

I can't provide a minimal repro because of the number of variables involved (and the fact that it depends on the profiling API makes it even harder). However I have a memory dump that I can share, and I can reproduce the issue fairly consistently on my machine.

Reproduction Steps

Expected behavior

The rejitted method should be called normally.

Actual behavior

Invocation crashes with an access violation.

Regression?

No response

Known Workarounds

No response

Configuration

• .NET 6.0.10
• x86 / ARM64

Other information

No response

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

Issue Details

---

Description

We have noticed crashes in our CI when running tests with our profiler. We've seen crashes with .NET 6 on x86 and ARM64, but other runtime versions or platforms could also be impacted. The process crashes with an AccessViolation/Segfault during shutdown.

I managed to capture a memory dump and found a few things:

• The shutdown is initiated by a call to Environment.Exit(0)
• During shutdown, the System.AppContext::OnProcessExit event is raised, and our event handler tries to send stuff via HTTP
• System.Net.Http.HttpClientHandler.SendAsync tries to call System.Net.Http.SocketsHttpHandler.SendAsync
• During the method call, the execution jumps to address 0x0 and causes the crash

The method call in HttpClientHandler.SendAsync looks like:

0ff772e3 8b4da4          mov     ecx,dword ptr [ebp-5Ch]
0ff772e6 8b55e0          mov     edx,dword ptr [ebp-20h]
0ff772e9 8b45a4          mov     eax,dword ptr [ebp-5Ch]
0ff772ec 8b00            mov     eax,dword ptr [eax]
0ff772ee 8b4028          mov     eax,dword ptr [eax+28h]
0ff772f1 ff5014          call    dword ptr [eax+14h]

As far as I can tell, mov eax,dword ptr [ebp-5Ch] moves the address of the HttpClientHandler to eax. Then mov eax,dword ptr [eax] reads the method table, and the next two instructions fetch the destination of the call (I'm not familiar with the layout of the method table).

call dword ptr [eax+14h] ends up calling the address 0ff7c990 which is just a jump:

0:011> !U 0ff7c990
Unmanaged code
0ff7c990 e94b050100      jmp     0ff8cee0

Then 0ff8cee0 contains the tiered jit stub:

0:011> !U 0ff8cee0
Unmanaged code
0ff8cee0 b884bd3d0f      mov     eax,0F3DBD84h
0ff8cee5 66ff08          dec     word ptr [eax]
0ff8cee8 0f85123107f0    jne     00000000
0ff8ceee e8fff36540      call    coreclr!OnCallCountThresholdReachedStub (505ec2f2)

Notice the jne 00000000, which causes the access violation.

A few things to note:

• We rejitted HttpClientHandler.SendAsync:

0:011> !DumpMD /d 0d15a570
Method Name:          System.Net.Http.HttpClientHandler.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
Class:                0d168388
MethodTable:          0d15a67c
mdToken:              0600029D
Module:               0d156d20
IsJitted:             yes
Current CodeAddr:     0ff77258
Version History:
  ILCodeVersion:      0CDD5E30
  ReJIT ID:           4
  IL Addr:            0ff57550
     CodeAddr:           0ff77258  (QuickJitted)
     NativeCodeVersion:  0CE8F538
  ILCodeVersion:      00000000
  ReJIT ID:           0
  IL Addr:            7819b150
     CodeAddr:           78126a30  (ReadyToRun)
     NativeCodeVersion:  00000000

• We rejitted SocketsHttpHandler.SendAsync:

0:011> !DumpMD /d 0d15d558
Method Name:          System.Net.Http.SocketsHttpHandler.SendAsync(System.Net.Http.HttpRequestMessage, System.Threading.CancellationToken)
Class:                0d16a568
MethodTable:          0d15d58c
mdToken:              0600085A
Module:               0d156d20
IsJitted:             yes
Current CodeAddr:     0ffb0010
Version History:
  ILCodeVersion:      0CDD5890
  ReJIT ID:           6
  IL Addr:            0ff5be48
     CodeAddr:           0ffb0010  (QuickJitted)
     NativeCodeVersion:  0CE90488
  ILCodeVersion:      00000000
  ReJIT ID:           0
  IL Addr:            781c3258
     CodeAddr:           7816a5b0  (ReadyToRun)
     NativeCodeVersion:  00000000

I'm not sure where to go from there. If I add a Thread.Sleep at the beginning of the test then I can't reproduce the issue anymore, so the timing seems important. It's possible that we have a bug in our profiler and we don't handle rejitting correctly, but even in that case I feel like the JIT should never end up writing an empty address in the stub.

I can't provide a minimal repro because of the number of variables involved (and the fact that it depends on the profiling API makes it even harder). However I have a memory dump that I can share, and I can reproduce the issue fairly consistently on my machine.

Reproduction Steps

Expected behavior

The rejitted method should be called normally.

Actual behavior

Invocation crashes with an access violation.

Regression?

No response

Known Workarounds

No response

Configuration

• .NET 6.0.10
• x86 / ARM64

Other information

No response

Author:	kevingosse
Assignees:	-
Labels:	area-CodeGen-coreclr
Milestone:	-

[OmerRaviv]

Hi there! I'm a colleague of @kevingosse and wanted to add some more info on this that we recently discovered.

1. We have validated that the issue does not reproduce at all if we disable tiered compilation, which makes us suspect that this might be a bug related to the interaction between ReJIT and tiered compilation. /cc @davmason @noahfalk
2. As Kevin mentioned, what's somewhat unique about this issue is that it happens when a method we rejitted (HttpClientHandler.SendAsync) attempts to call another method we rejitted (SocketsHttpHandler.SendAsync)
3. We have found another couple of instances of this AccessViolationException, that do not seem to be related to the app being shutdown. Both are Windows x64, net6.0:

• Dump file Native pdb 1, Native pdb 2
• Dump file, Native pdb 1, Native pdb 2

What you'll see in the dump is that as Kevin reported, the access violation happens as part of the call to OnCallCountThresholdReachedStub.

[davmason]

Hi @OmerRaviv @kevingosse

Sorry for the delay, I don't get notified for the area-vm-coreclr tag. Looking at the dumps you provided I see evidence of stack corruption, a few different threads have stacks that are broken like this:

  28  Id: 1870.19bc Suspend: 0 Teb: 00000004`d70be000 Unfrozen "Console logger queue processing thread"
 # Child-SP          RetAddr               Call Site
00 00000004`d98beb88 00007ff9`c2aefebc     ntdll!NtWaitForMultipleObjects+0x14
01 00000004`d98beb90 00007ff9`8d59587f     KERNELBASE!WaitForMultipleObjectsEx+0xec
02 (Inline Function) --------`--------     coreclr!Thread::DoAppropriateAptStateWait+0x41 [D:\a\_work\1\s\src\coreclr\vm\threads.cpp @ 3394] 
03 00000004`d98bee80 00007ff9`8d5956f1     coreclr!Thread::DoAppropriateWaitWorker+0x14f [D:\a\_work\1\s\src\coreclr\vm\threads.cpp @ 3526] 
04 00000004`d98bef70 00007ff9`8d5948c6     coreclr!Thread::DoAppropriateWait+0x89 [D:\a\_work\1\s\src\coreclr\vm\threads.cpp @ 3243] 
05 (Inline Function) --------`--------     coreclr!CLREventBase::WaitEx+0x36 [D:\a\_work\1\s\src\coreclr\vm\synch.cpp @ 459] 
06 (Inline Function) --------`--------     coreclr!CLREventBase::Wait+0x41 [D:\a\_work\1\s\src\coreclr\vm\synch.cpp @ 412] 
07 (Inline Function) --------`--------     coreclr!Thread::Wait+0x41 [D:\a\_work\1\s\src\coreclr\vm\threads.cpp @ 4006] 
08 (Inline Function) --------`--------     coreclr!Thread::Block+0x49 [D:\a\_work\1\s\src\coreclr\vm\threads.cpp @ 3963] 
09 00000004`d98beff0 00007ff9`8d59469d     coreclr!SyncBlock::Wait+0x1c6 [D:\a\_work\1\s\src\coreclr\vm\syncblk.cpp @ 2867] 
0a (Inline Function) --------`--------     coreclr!ObjHeader::Wait+0x42 [D:\a\_work\1\s\src\coreclr\vm\syncblk.cpp @ 2266] 
0b (Inline Function) --------`--------     coreclr!Object::Wait+0x42 [D:\a\_work\1\s\src\coreclr\vm\object.h @ 337] 
0c 00000004`d98bf110 00007ff9`8cdf1952     coreclr!ObjectNative::WaitTimeout+0xcd [D:\a\_work\1\s\src\coreclr\classlibnative\bcltype\objectnative.cpp @ 266] 
0d 00000004`d98bf290 00007ff9`8ce03709     System_Private_CoreLib!System.Threading.Monitor.Wait+0x22 [/_/src/coreclr/System.Private.CoreLib/src/System/Threading/Monitor.CoreCLR.cs @ 159] 
0e 00000004`d98bf2d0 00007ff9`8ce034b1     System_Private_CoreLib!System.Threading.SemaphoreSlim.WaitUntilCountOrTimeout+0x39 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/SemaphoreSlim.cs @ 444] 
0f 00000004`d98bf320 00007ff9`2e3df1ea     System_Private_CoreLib!System.Threading.SemaphoreSlim.Wait+0x161 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/SemaphoreSlim.cs @ 365] 
10 00000004`d98bf3d0 00000184`c9645e00     System_Collections_Concurrent!System.Collections.Concurrent.BlockingCollection<Microsoft.Extensions.Logging.Console.LogMessageEntry>.TryTakeWithNoTimeValidation+0x10a [/_/src/libraries/System.Collections.Concurrent/src/System/Collections/Concurrent/BlockingCollection.cs @ 700] 
11 00000004`d98bf3d8 00000004`d98bf498     0x00000184`c9645e00
12 00000004`d98bf3e0 00000183`c9593420     0x00000004`d98bf498
13 00000004`d98bf3e8 00000000`00000000     0x00000183`c9593420

Usually this means something is overwriting a buffer or similar, and it means it is very difficult or impossible to debug from a dump file. Are you able to isolate the issue and get a trace?

[davmason]

Also, forgot to mention, once stack corruption is involved then we can't trust anything and it would cause random AVs like you are seeing.

[jkotas]

a few different threads have stacks that are broken like this:

I think that this is just a sign of unreliable stackwalking in widbg. It is not unusual to see that on dumps. Try running !clrstack that is more reliable. It should give you a complete managed stacktrace.

What you'll see in the dump is that as Kevin reported, the access violation happens as part of the call to OnCallCountThresholdReachedStub

Yes, I see that as well. This is from thread 16c4 in the first dump:

00007ffc`8a21f870 48b878c0f3e4de010000 mov rax,1DEE4F3C078h
00007ffc`8a21f87a 66ff08          dec     word ptr [rax]
00007ffc`8a21f87d 740c            je      00007ffc`8a21f88b
00007ffc`8a21f87f 48b80000000000000000 mov rax,0 <- this should not be 0
00007ffc`8a21f889 ffe0            jmp     rax

Looks like we are setting a wrong target address for the call-counting stubs of Rejited methods.