Loader\\binding\\tracing\\BinderTracingTest.Basic\\BinderTracingTest.Basic Asserts when Crossgen2-compiled

[trylek]

The failure appeared on 4/2 between 5.46 AM and 10.48 AM PST - I was testing the same change twice due to rebasing after hitting a merge conflict - the first instance passed and the second failed. Since then I see another run fail in the same test.

OS: All (Windows / Linux / OSX)
Architectures: All

Successful run:

https://dev.azure.com/dnceng/public/_build/results?buildId=585404&view=results

Failed run:

https://dev.azure.com/dnceng/public/_build/results?buildId=587104&view=results

Error transcript:

Return code: 1
Raw output file: /private/tmp/helix/working/982308E2/w/9E2708AE/e/Loader/binding/Reports/Loader.binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.output.txt
Raw output:
BEGIN EXECUTION
in takeLock
Emitting R2R PE file: /private/tmp/helix/working/982308E2/w/9E2708AE/e/Loader/binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.dll

in ReleaseLock
/tmp/helix/working/982308E2/p/corerun BinderTracingTest.Basic.dll ''
Running LoadFile...
Running LoadBytes...
Running LoadFromStream...
Running LoadFromAssemblyPath...
Launching process for LoadFromAssemblyName...
Running LoadFromAssemblyName...

Launching process for LoadFrom...
Running LoadFrom...

Launching process for PlatformAssembly...
Running PlatformAssembly...

Launching process for PlatformAssembly_Cached...
Running PlatformAssembly_Cached...

Launching process for Reflection...
Running Reflection...

Launching process for Reflection_Cached...
Running Reflection_Cached...

Launching process for Reflection_CustomALC...
Running Reflection_CustomALC...

Launching process for ContextualReflection_DefaultToCustomALC...
Running ContextualReflection_DefaultToCustomALC...

Launching process for ContextualReflection_CustomToDefaultALC...
Running ContextualReflection_CustomToDefaultALC...

Launching process for JITLoad...
Running JITLoad...
Test JITLoad failed: TestLibrary.AssertTestException: Assert.AreEqual: Expected: [Default]. Actual: []. Unexpected value for RequestingAssemblyLoadContext on event
 at TestLibrary.Assert.HandleFail(String assertionName, String message) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Common/CoreCLRTestLibrary/Assertion.cs:line 735
 at TestLibrary.Assert.AreEqual[T](T expected, T actual, String message) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Common/CoreCLRTestLibrary/Assertion.cs:line 414
 at BinderTracingTests.Helpers.ValidateBindOperation(BindOperation expected, BindOperation actual) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Loader/binding/tracing/Helpers.cs:line 24
 at BinderTracingTests.BinderTracingTest.ValidateSingleBind(BinderEventListener listener, AssemblyName assemblyName, BindOperation expected) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Loader/binding/tracing/BinderTracingTest.cs:line 203
 at BinderTracingTests.BinderTracingTest.RunSingleTest(MethodInfo method) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Loader/binding/tracing/BinderTracingTest.cs:line 159

Expected: 100
Actual: 101
END EXECUTION - FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=/tmp/helix/working/982308E2/p
> /private/tmp/helix/working/982308E2/w/9E2708AE/e/Loader/binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.sh
Expected: True
Actual: False

Stack trace
   at Loader_binding._tracing_BinderTracingTest_Basic_BinderTracingTest_Basic_._tracing_BinderTracingTest_Basic_BinderTracingTest_Basic_sh() in /Users/runner/runners/2.165.2/work/1/s/artifacts/tests/coreclr/OSX.x64.Checked/TestWrappers/Loader.binding/Loader.binding.XUnitWrapper.cs:line 140

[trylek]

FWIW the failure doesn't repro in Crossgen1 runs (I tried runtime-coreclr r2r on master and it passed whereas a crossgen2 run on master fails right now).

[AriNuer]

Test Loader/binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.sh failed here again:
runtime-coreclr crossgen2:20200406.1

Error message:

Return code: 1
Raw output file: /home/helixbot/work/B5CD0974/w/A3E70916/e/Loader/binding/Reports/Loader.binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.output.txt
Raw output:
BEGIN EXECUTION
in takeLock
Emitting R2R PE file: /home/helixbot/work/B5CD0974/w/A3E70916/e/Loader/binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.dll
in ReleaseLock
/home/helixbot/work/B5CD0974/p/corerun BinderTracingTest.Basic.dll ''
Running LoadFile...\nRunning LoadBytes...\nRunning LoadFromStream...
Running LoadFromAssemblyPath...
Launching process for LoadFromAssemblyName...
Running LoadFromAssemblyName...
Launching process for LoadFrom...
Running LoadFrom...
Launching process for PlatformAssembly...
Running PlatformAssembly...
Launching process for PlatformAssembly_Cached...
Running PlatformAssembly_Cached...
Launching process for Reflection...
Running Reflection...
Launching process for Reflection_Cached...
Running Reflection_Cached...
Launching process for Reflection_CustomALC...
Running Reflection_CustomALC...
Launching process for ContextualReflection_DefaultToCustomALC...
Running ContextualReflection_DefaultToCustomALC...
Launching process for ContextualReflection_CustomToDefaultALC...
Running ContextualReflection_CustomToDefaultALC...
Launching process for JITLoad...
Running JITLoad...
Test JITLoad failed: TestLibrary.AssertTestException: Assert.AreEqual: Expected: [Default]. Actual: []. Unexpected value for RequestingAssemblyLoadContext on event
at TestLibrary.Assert.HandleFail(String assertionName, String message) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Common/CoreCLRTestLibrary/Assertion.cs:line 735
at BinderTracingTests.Helpers.ValidateBindOperation(BindOperation expected, BindOperation actual) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Loader/binding/tracing/Helpers.cs:line 24
at BinderTracingTests.BinderTracingTest.ValidateSingleBind(BinderEventListener listener, AssemblyName assemblyName, BindOperation expected) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Loader/binding/tracing/BinderTracingTest.cs:line 203
at BinderTracingTests.BinderTracingTest.RunSingleTest(MethodInfo method) in /Users/runner/runners/2.165.2/work/1/s/src/coreclr/tests/src/Loader/binding/tracing/BinderTracingTest.cs:line 159
Expected: 100
Actual: 101
END EXECUTION - FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=/home/helixbot/work/B5CD0974/p
> /home/helixbot/work/B5CD0974/w/A3E70916/e/Loader/binding/tracing/BinderTracingTest.Basic/BinderTracingTest.Basic.sh
Expected: True
Actual: False

Stack trace:

   at Loader_binding._tracing_BinderTracingTest_Basic_BinderTracingTest_Basic_._tracing_BinderTracingTest_Basic_BinderTracingTest_Basic_sh() in /__w/1/s/artifacts/tests/coreclr/Linux.x64.Checked/TestWrappers/Loader.binding/Loader.binding.XUnitWrapper.cs:line 140

Details:
https://dev.azure.com/dnceng/public/_build/results?buildId=591189&view=ms.vss-test-web.build-test-results-tab&runId=18629256&resultId=101336&paneView=debug

[nattress]

This regression in crossgen2 is caused by c8b9cf1 where we now skip prepopulating _assemblyRefToModuleIdMap if IsInputBubble == true. I'm not sure what the root cause here is yet, but it seems fishy that when we skip prepopulating _assemblyRefToModuleIdMap, we still set _nextModuleId to be 1 after _assemblyRefCount. Then in ManifestMetadataTableNode.ModuleToIndexInternal if we encounter a reference that is in the assembly ref list, we assign it a new, higher assemblyRefIndex than we would if we had prepopulated the list.

[trylek]

I believe Jan's point was to make sure all reference assemblies make it to the manifest metadata as some runtime typesystem code says that "reference assembly A is in the same version bubble iff it's in the manifest metadata" that reference assemblies resolved through the AssemblyRef table didn't satisfy. I was under the impression that the change was passing basic validation but the offset calculation is somewhat subtle and it's possible that some bug remained.