[NativeAOT/win-x86] System.Runtime.Tests crash

[jkotas]

Running assembly:System.Runtime.Tests, Version=9.0.0.0, Culture=neutral, PublicKeyToken=cc7b13ffcd2ddd51
[SKIP] System.Reflection.Tests.InvokeWithRefLikeArgs.MethodTakesRefToRefStructAsArg_ThrowsNSE
[SKIP] System.Reflection.Tests.NullabilityInfoContextTests.VerifyIsSupportedWorks
[SKIP] System.Reflection.Tests.NullabilityInfoContextTests.VerifyIsSupportedThrows
[SKIP] System.Reflection.Tests.ModuleTests.ResolveMethodsByMethodInfo
[SKIP] System.Reflection.Tests.ModuleTests.ResolveFieldFail
[SKIP] System.Reflection.Tests.ModuleTests.ResolveFieldsByMemberInfo
[SKIP] System.Reflection.Tests.ModuleTests.ResolveTypeFail
[SKIP] System.Reflection.Tests.ModuleTests.ResolveMethodsByMemberInfo
[SKIP] System.Reflection.Tests.ModuleTests.ResolveStringFail
[SKIP] System.Reflection.Tests.ModuleTests.ResolveFieldsByFieldInfo
[SKIP] System.Reflection.Tests.ModuleTests.ResolveTypes
[SKIP] System.Reflection.Tests.ModuleTests.ResolveTypesByMemberInfo
[SKIP] System.Reflection.Tests.ModuleTests.ResolveMethodFail
[SKIP] System.Reflection.Tests.ModuleTests.ResolveMethodOfGenericClass
[SKIP] System.Runtime.Tests.JitInfoTests.JitInfoCurrentThreadIsPopulated
[SKIP] System.Runtime.Tests.JitInfoTests.JitInfoIsNotPopulated
[SKIP] System.Runtime.Tests.JitInfoTests.JitInfoIsPopulated
----- end Mon 04/01/2024 21:39:10.34 ----- exit code -1073740286 ----------------------------------------------------------

Details: https://dev.azure.com/dnceng-public/public/_build/results?buildId=626098&view=ms.vss-test-web.build-test-results-tab&runId=15355874&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab&resultId=172764

The crash is caused by unmanaged IP at this stacktrace:

0:006> k
 # ChildEBP RetAddr      
00 0a53ebdc 01247789     System_Runtime_Tests!StackFrameIterator::CalculateCurrentMethodState+0x71 [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\StackFrameIterator.cpp @ 1674] 
01 0a53ebec 01247548     System_Runtime_Tests!StackFrameIterator::NextInternal+0x219 [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\StackFrameIterator.cpp @ 1476] 
02 0a53ebf4 0123fc3c     System_Runtime_Tests!StackFrameIterator::Next+0x8 [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\StackFrameIterator.cpp @ 1265] 
03 0a53ec1c 0123faad     System_Runtime_Tests!Thread::GcScanRootsWorker+0x17c [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\thread.cpp @ 547] 
04 0a53ecec 012459ab     System_Runtime_Tests!Thread::GcScanRoots+0x6d [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\thread.cpp @ 411] 
05 0a53ed0c 0126541c     System_Runtime_Tests!GCToEEInterface::GcScanRoots+0xeb [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\gcenv.ee.cpp @ 125] 
06 0a53ed90 0125f16e     System_Runtime_Tests!WKS::gc_heap::mark_phase+0x2ec [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 29613] 
07 0a53ee04 0125f034     System_Runtime_Tests!WKS::gc_heap::gc1+0xfe [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 22183] 
08 0a53ee28 012510e3     System_Runtime_Tests!WKS::gc_heap::garbage_collect+0x694 [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 24196] 
09 0a53ee48 0126e3e3     System_Runtime_Tests!WKS::GCHeap::GarbageCollectGeneration+0x2c3 [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 50698] 
0a 0a53ee58 01254996     System_Runtime_Tests!WKS::gc_heap::trigger_gc_for_alloc+0x53 [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 18781] 
0b (Inline) --------     System_Runtime_Tests!WKS::gc_heap::try_allocate_more_space+0x176 [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 18901] 
0c 0a53ee84 012503fe     System_Runtime_Tests!WKS::gc_heap::allocate_more_space+0x186 [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 19401] 
0d (Inline) --------     System_Runtime_Tests!WKS::gc_heap::allocate+0x22 [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 19432] 
0e 0a53eed0 0123ef97     System_Runtime_Tests!WKS::GCHeap::Alloc+0xce [D:\a\_work\1\s\src\coreclr\gc\gc.cpp @ 49630] 
0f 0a53eef0 0123f4c8     System_Runtime_Tests!GcAllocInternal+0xa7 [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\GCHelpers.cpp @ 542] 
10 0a53ef18 0123dfaf     System_Runtime_Tests!RhpGcAlloc+0x48 [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\GCHelpers.cpp @ 603] 
11 0a53ef50 014bd3c3     System_Runtime_Tests!RhNewString+0x77 [D:\a\_work\1\s\src\coreclr\nativeaot\Runtime\i386\AllocFast.asm @ 215] 
12 0a53ef60 015a203e     System_Runtime_Tests!String__Ctor_7+0x23 [/_/src/libraries/System.Private.CoreLib/src/System/String.cs @ 317] 
13 0a53ef7c 01749bbf     System_Runtime_Tests!System.Runtime.CompilerServices.DefaultInterpolatedStringHandler__ToStringAndClear+0x1e [/_/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/DefaultInterpolatedStringHandler.cs @ 112] 
14 0a53efa4 017497b3     System_Runtime_Tests!System_Runtime_Tests_System_Text_Unicode_Tests_Utf8Tests__ToUtf16+0xef [/_/src/libraries/System.Runtime/tests/System.Runtime.Tests/System/Text/Unicode/Utf8Tests.cs @ 118] 
...

[jkotas]

cc @filipnavara

[dotnet-policy-service]

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

[filipnavara]

This seems to be some issue with the suspend redirection. There are some visible mismatches in the values of FrameIterator and the initial suspended context, possibly because it already tried to unwind from some inconsistent state. It may take me some time to get to the bottom of this.

[filipnavara]

Thread 6 is doing the GC stackwalk of Thread 5 with the following stack trace:

[0x8]   System_Runtime_Tests!S_P_StackTraceMetadata_Internal_StackTraceMetadata_StackTraceMetadata_PerModuleMethodNameResolver___ctor+0xe7   0xa1de974   0x1604389   
[0x9]   System_Runtime_Tests!S_P_StackTraceMetadata_Internal_StackTraceMetadata_StackTraceMetadata_PerModuleMethodNameResolverHashtable__CreateValueFromKey+0x19   0xa1de9a8   0x1602fc8   
[0xa]   System_Runtime_Tests!S_P_StackTraceMetadata_Internal_StackTraceMetadata_StackTraceMetadata__GetMethodNameFromStartAddressIfAvailable+0x148   0xa1de9c4   0x15cedab   
[0xb]   System_Runtime_Tests!Internal.DeveloperExperience.DeveloperExperience__GetMethodName+0x2b   0xa1deaf8   0x15ceba3   
[0xc]   System_Runtime_Tests!Internal.DeveloperExperience.DeveloperExperience__CreateStackTraceString+0x23   0xa1deb04   0x15834db   
[0xd]   System_Runtime_Tests!System.Diagnostics.StackFrame__AppendToStackTrace+0x2b   0xa1deb44   0x158391d   
[0xe]   System_Runtime_Tests!System.Diagnostics.StackTrace__ToString+0x3d   0xa1deb64   0x1583a01   
[0xf]   System_Runtime_Tests!System.Diagnostics.StackTrace__ToString_1+0x31   0xa1deb80   0x14c95c7   
[0x10]   System_Runtime_Tests!System.Exception__get_StackTrace+0x57   0xa1deb98   0x1814dfd   
[0x11]   System_Runtime_Tests!System_Runtime_Tests_System_Tests_ExceptionTests__ThrowStatementDoesNotResetExceptionStackLineOtherMethod+0x2d   0xa1debac   0x22483db   
[0x12]   System_Runtime_Tests!Internal_CompilerGenerated__Module___<DynamicInvoke>Static<System.Void>+0xb   0xa1deebc   0x15aab90   
[0x13]   System_Runtime_Tests!System.Reflection.DynamicInvokeInfo__Invoke+0x90   0xa1deec4   0x160173f   
[0x14]   System_Runtime_Tests!S_P_Reflection_Execution_Internal_Reflection_Execution_MethodInvokers_StaticMethodInvoker__Invoke+0x1f   0xa1deef4   0x15cf6d4   
[0x15]   System_Runtime_Tests!Internal.Reflection.Core.Execution.MethodBaseInvoker__Invoke+0x34   0xa1def0c   0x15b7b29   
[0x16]   System_Runtime_Tests!System.Reflection.Runtime.MethodInfos.RuntimeMethodInfo__Invoke+0x39   0xa1def2c   0x1fc9871

The mismatch seems to happen somewhere around frame 0x10:

[0x10]   System_Runtime_Tests!System.Exception__get_StackTrace+0x57   0xa1deb98   0x1814dfd   
[0x11]   System_Runtime_Tests!System_Runtime_Tests_System_Tests_ExceptionTests__ThrowStatementDoesNotResetExceptionStackLineOtherMethod+0x2d   0xa1debac   0x22483db   

The frame iterator has the following values:

m_EffectiveSafePoint = 0x1814dfd;  // frame 0x10 return address
m_RegDisplay.SP = 0x0a1debb0; // off-by-DWORD, should be 0xa1debac, probably?
m_RegDisplay.PCTAddr = 0x0a1debac; // also off-by-DWORD, presumably?

Let's check the memory:

0:006> dd 0x0a1deba8
0a1deba8  01814dfd 023b35a4

// 01814dfd is System_Runtime_Tests!System_Runtime_Tests_System_Tests_ExceptionTests__ThrowStatementDoesNotResetExceptionStackLineOtherMethod+0x2d
// 023b35a4 is the bogus address that was loaded into m_ControlPC and caused the assert to fire

[filipnavara]

Still not sure what is going on.

This is GCInfo for System_Runtime_Tests!System.Exception__get_StackTrace:

{   
    CodeLength: 101 bytes
    InfoHdr:
        PrologSize: 6
        EpilogSize: 5
        EpilogCount: 3
        EpilogAtEnd: no
        Callee-saved regs  = EDI ESI EBX EBP
        EbpFrame: yes
        Fully Interruptible: no
        DoubleAlign: no
        Arguments Size: 0 DWORDs
        Stack Frame Size: 0 DWORDs
        UntrackedCnt: 0
        VarPtrTableSize: 0
        GenericsContext: 0
        GenericsContextIsMethodDesc: 0
        ReturnKind: RT_Object
        RevPInvokeOffset: 0
        Epilogs: 25 38 96
        GcSlots:
            -------------------------
    Size: 16 bytes
}

Looking the the frame iterator registry values:

pRbx: 0xa1deb98 : 0xa1deed8
pRbp: 0xa1deba4 : 0xa1deeb4
pRsi: 0xa1deb9c : 0xc97b49c
pRdi: 0xa1deba0 : 0x22483d0
SP: 0xa1debb0
PCTAddr: 0xa1debac

As established earlier, both PCTAddr and SP is +4 from the correct value. That means that pRbp looks correct, right? There's no caller arguments on the stack, so the next thing on the stack should be return address at 0x0a1deba8. Yet, PCTAddr is off by four. It's EBP based frame, so I would expect UnwindEbpDoubleAlignFrame to do the unwinding. We are neither in prolog nor in epilog. That basically narrows down the issue to be surfaced somewhere in this part of code and I just don't see how could we get a discrepancy in there:

runtime/src/coreclr/vm/gc_unwind_x86.inl

Lines 3037 to 3065 in 997f09c

	if (updateAllRegs)
	{
	// Get to the first callee-saved register
	PTR_DWORD pSavedRegs = PTR_DWORD((TADDR)curEBP);
	if (info->doubleAlign && (curEBP & 0x04))
	pSavedRegs--;
	for (unsigned i = 0; i < STRING_LENGTH(CALLEE_SAVED_REGISTERS_MASK); i++)
	{
	RegMask regMask = CALLEE_SAVED_REGISTERS_MASK[i];
	if ((info->savedRegMask & regMask) == 0)
	continue;
	SetLocation(pContext, i, --pSavedRegs);
	}
	}
	/* The caller's ESP will be equal to EBP + retAddrSize + argSize. */
	pContext->SP = (DWORD)(curEBP + sizeof(curEBP) + ESPIncrOnReturn(info));
	/* The caller's saved EIP is right after our EBP */
	SetRegdisplayPCTAddr(pContext, (TADDR)curEBP + RETURN_ADDR_OFFS * sizeof(TADDR));
	/* The caller's saved EBP is pointed to by our EBP */
	pContext->SetEbpLocation(PTR_DWORD((TADDR)curEBP));

[filipnavara]

Maybe I am misreading the situation and it's trying to unwind the next frame after this one. That's inside a handler region so it's more likely something specific to funclets. I'll check that code path next; I need to update my unwind info dumper first to handle that.

[jkotas]

It is likely to reproduce in a standalone repro on a private build with GC.Collect added CreateStackTraceString. It will allow you to step through it in a debugger. (If it repros, I would collect TTD trace and step through it back and forth until I would figure it out.)

[filipnavara]

It is likely to reproduce in a standalone repro on a private build with GC.Collect added CreateStackTraceString.

Thanks. I will try that.

I would collect TTD trace

Unfortunately TTD is broken on my machine. That said, I don't think I would need it if it reproduces.

I am now convinced that there's an attempt to unwind the handler funclet in System_Runtime_Tests_System_Tests_ExceptionTests__ThrowStatementDoesNotResetExceptionStackLineOtherMethod. My unwind dumper tool relies on ILCompiler.Reflection.ReadyToRun to dump the GCInfo and there's currently no code to decode the x86 argument tables. There are three push instructions at the beginning of the handler and if it was not correctly accounted for then it would explain the discrepancy.