Assert failure !CREATE_CHECK_STRING(pMT && pMT->Validate()) during PInvokeTests.VarargsTest.TestEntryPoint on win-x86

[jakobbotsch]

gcstress-extra failure: https://dev.azure.com/dnceng-public/public/_build/results?buildId=1056333&view=results
Console log: https://helixr1107v0xdcypoyl9e7f.blob.core.windows.net/dotnet-runtime-refs-heads-main-cb88d2e3d27e4b4ca7/Interop.0.1/1/console.f7d59f82.log?helixlogtype=result

22:59:16.752 Running test: global::PInvokeTests.VarargsTest.TestEntryPoint()

Assert failure(PID 7304 [0x00001c88], Thread: 10504 [0x2908]): !CREATE_CHECK_STRING(pMT && pMT->Validate())

CORECLR! Object::ValidateInner + 0x145 (0x73308445)
CORECLR! Object::Validate + 0x98 (0x733082c8)
CORECLR! WKS::GCHeap::Relocate + 0x51 (0x7362d7d1)
CORECLR! MetaSig::GcScanRoots + 0x2D3 (0x7333d570)
CORECLR! promoteVarArgs + 0x172 (0x73233ef2)
CORECLR! EnumGcRefsX86 + 0x12F5 (0x7322f615)
CORECLR! EECodeManager::EnumGcRefs + 0x19B (0x7322e2db)
CORECLR! GcStackCrawlCallBack + 0x2BC (0x73423d7c)
CORECLR! Thread::MakeStackwalkerCallback + 0x4B (0x733466fc)
CORECLR! Thread::StackWalkFramesEx + 0xEC (0x733477cd)
    File: D:\a\_work\1\s\src\coreclr\vm\object.cpp:548
    Image: C:\h\w\B7D20975\p\corerun.exe

(Note promoteVarArgs in call stack.)

[dotnet-policy-service]

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

[filipnavara]

The argsStart calculated before calling promoteVarArgs is 0x0317e4f8.

Let's look at the memory at that location, it is the managed IL stub for TestVarArgs:

runtime/src/tests/Interop/PInvoke/Varargs/VarargsTest.cs

Line 17 in 39e8c08

private static extern void TestVarArgs(StringBuilder builder, IntPtr bufferSize, string formatString, __arglist);

called from here:

runtime/src/tests/Interop/PInvoke/Varargs/VarargsTest.cs

Line 54 in 39e8c08

TestVarArgs(builder, (IntPtr)30, "%i, %i, %.1f", __arglist(arg1, arg2, arg3));

0317e4f8  094ab788 00000000 40290000 00000014
0317e508  0000000a 089c3b34 0000001e 059d6d14

059d6d14 is pointer to zeros (should be the StringBuilder?)
0000001e is 30
089c3b34 is string object with the value "%i, %i, %.1f"
0000000a is arg1
00000014 is arg2
00000000 40290000 is arg3

094ab788 is varArgSig with sizeOfArgs == 0x20 (does this look correct?; UPD: VM comment mentions it's an "upper estimate", so probably ok)

argOffset in promoteVarArgs is 0x38 (looks wrong to me).

(the values in the parameters themselves looks quite okay to me; the iteration not so much, it dies when reporting 059d6d14 which is the last value in the memory above)

In case it is relevant, here are few more variables from promoteVarArgs:
pFrameBase is 0x317e4dc, argsStart is 0x317e4f8
msig.m_nArgs is 6
msig.m_iCurArg is 1

[filipnavara]

So yeah, looks like a GC hole. We lost track of the StringBuilder somewhere.

Stress log: https://gist.githubusercontent.com/filipnavara/21fe8a612e467a9c817b21aa7510ed20/raw/dcb0454cfd871df1efcfb55cbe6c502d216c8930/gistfile1.txt

[filipnavara]

So, the misreported object is 059d6d14. Stress log lists:

2908  50.817398769 : `GCROOTS`            Scanning Frameless method 09185734 (Program.<<Main>$>g__TestExecutor162|25_163(System.IO.StreamWriter, System.IO.StreamWriter, <>c__DisplayClass25_0 ByRef)) EIP = 037A6A00 &EIP = 0317E558

2908  50.817398500 : `EH`GCROOTS`         CrawlFrame (0317B9EC): Frameless: Yes CallerSP: 0317E5DC

2908  50.817395338 : `GC`GCROOTS`             GC Root 0317E524 RELOCATED 059D6D14 -> 059D5D18  MT = 09A55EC4 (System.Text.StringBuilder)

2908  50.817395264 : `GC`GCROOTS`             GC Root 0317E528 RELOCATED 059D6CDC -> 059D5CE0  MT = 055EE754 (System.Double)

2908  50.817395186 : `GC`GCROOTS`             GC Root 0317E52C RELOCATED 059D6CD0 -> 059D5CD4  MT = 05529D04 (System.Int32)

2908  50.817395109 : `GC`GCROOTS`             GC Root 0317E530 RELOCATED 059D6CC4 -> 059D5CC8  MT = 05529D04 (System.Int32)

2908  50.817394979 : `GC`GCROOTS`             GC Root 0317E534 RELOCATED 059D6CAC -> 059D5CB0  MT = 05523ECC (System.Object[])

2908  50.817394900 : `GC`GCROOTS`             GC Root 0317E538 RELOCATED 059D6D14 -> 059D5D18  MT = 09A55EC4 (System.Text.StringBuilder)

2908  50.817394758 : `GC`GCROOTS`             GC Root 0317E53C RELOCATED 059D6CEC -> 059D5CF0  MT = 05608FC4 (System.String)

2908  50.817393295 : `GCROOTS`            Scanning Frameless method 037D5B14 (PInvokeTests.VarargsTest.TestEntryPoint()) EIP = 037A6D5A &EIP = 0317E4F4

2908  50.817393011 : `EH`GCROOTS`         CrawlFrame (0317B9EC): Frameless: Yes CallerSP: 0317E55C

2908  50.817389280 : `GCROOTS`            Scanning Frameless method 037D6E0C (ILStubClass.IL_STUB_PInvoke(System.Text.StringBuilder, IntPtr, System.String, Int32, Int32, Double, ...)) EIP = 037A7071 &EIP = 0317E414

2908  50.817388847 : `GCROOTS`            STACKWALK: Reached parent of non-filter funclet @ CallerSP: 0317E4F8, m_crawl.pFunc = 037D6E0C

2908  50.817388700 : `EH`GCROOTS`         CrawlFrame (0317B9EC): Frameless: Yes CallerSP: 0317E4F8

2908  50.817385774 : `GC`GCROOTS`             GC Root 0317E460 RELOCATED 059D6D14 -> 059D5D18  MT = 09A55EC4 (System.Text.StringBuilder)

2908  50.817385662 : `GC`GCROOTS`             GC Root 0317E464 RELOCATED 059D6D14 -> 059D5D18  MT = 09A55EC4 (System.Text.StringBuilder)

and the object exists at the relocated address:

0:000> !do 059D5D18
Name:        System.Text.StringBuilder
MethodTable: 09a55ec4
Canonical MethodTable: 09a55ec4
Tracked Type: false
Size:        28(0x1c) bytes
File:        C:\h\w\B7D20975\p\System.Private.CoreLib.dll
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
09a5223c  40010b2        4        System.Char[]  0 instance 059d5d34 m_ChunkChars
09a55ec4  40010b3        8 ...ext.StringBuilder  0 instance 00000000 m_ChunkPrevious
05529d04  40010b4        c         System.Int32  1 instance       12 m_ChunkLength
05529d04  40010b5       10         System.Int32  1 instance        0 m_ChunkOffset
05529d04  40010b6       14         System.Int32  1 instance 2147483647 m_MaxCapacity

so apparently the reference in stack arguments was not updated.

(Based on the stack walk it seems to be fallout from x86/funclets; I am not sure why the frame was skipped but this is similar to a previous case which I debugged. Now that I know when the missed reporting happened it should be possible to re-run it with TTD and then carefully put breakpoints to get into the right stack walk iteration. Then it's just a matter of observing the values and figuring out the logic flaw.)

[filipnavara]

This is similar to an earlier flaw...

ILStubClass.IL_STUB_PInvoke has exception handling which produces two frames for the stack walk. The stack walker expects the funclet to report all GC roots and then skips the non-funclet parent and doesn't ask it to report anything. Apparently we don't promote varargs when enumerating GC roots of a funclet:

runtime/src/coreclr/vm/gc_unwind_x86.inl

Lines 3912 to 3922 in 664ac25

	#ifdef FEATURE_EH_FUNCLETS // funclets
	//
	// If we're in a funclet, we do not want to report the incoming varargs. This is
	// taken care of by the parent method and the funclet should access those arguments
	// by way of the parent method's stack frame.
	//
	if (isFunclet)
	{
	return true;
	}
	#endif // FEATURE_EH_FUNCLETS