[runincontext] Test failed: tracing_eventpipe._buffersize_buffersize_buffersize_._buffersize_buffersize_buffersize_cmd

[VincentBu]

Job:
https://mc.dot.net/#/user/coreclr-runincontext/ci~2Fdotnet~2Fcoreclr~2Frefs~2Fheads~2Fmaster/test~2Ffunctional~2Fcli~2F/20190721.1/workItem/PayloadGroup0/analysis/xunit/tracing_eventpipe._buffersize_buffersize_buffersize_~2F_buffersize_buffersize_buffersize_cmd

Failed tests:
tracing_eventpipe.buffersize_buffersize_buffersize._buffersize_buffersize_buffersize_cmd

Log:

Return code:      1
Raw output file:      C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Work\\5095a7a2-9705-4c75-8202-63eb131acfd4\\Exec\\tracing\\eventpipe\\Reports\\tracing.eventpipe\\buffersize\\buffersize\\buffersize.output.txt
Raw output:
BEGIN EXECUTION
call C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Payload\\runincontext.cmd C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Work\\5095a7a2-9705-4c75-8202-63eb131acfd4\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\ buffersize.exe 
TEST STARTING
TEST PASSED!
TEST STARTING
TEST PASSED!
FAILURE: Unload failed

RunInContext FAIL! Exiting with code 213
Expected: 100
Actual: 213
END EXECUTION - FAILED
FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Payload
> C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Work\\5095a7a2-9705-4c75-8202-63eb131acfd4\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\buffersize.cmd
Expected: True
Actual:   False

[AaronRobinsonMSFT]

Could be related to: dotnet/coreclr#25786?

cc @jorive

[tommcdon]

@josalem @sywhang

[sywhang]

cc @jorive since he was investigating it this morning - Please let me know if you need any help with the investigation :)

[jorive]

This failure is for a runincontext.cmd test permutation.

[AriNuer]

Same test tracing_eventpipe._buffersize_buffersize_buffersize_/_buffersize_buffersize_buffersize_cmd failed with Timed out.

Message :

cmdLine:C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Work\\b883f6c8-423d-49c3-be11-0d7517474875\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\buffersize.cmd Timed Out

Return code:      -100
Raw output file:      C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Work\\b883f6c8-423d-49c3-be11-0d7517474875\\Exec\\tracing\\eventpipe\\Reports\\tracing.eventpipe\\buffersize\\buffersize\\buffersize.output.txt
Raw output:
BEGIN EXECUTION
        1 file(s) copied.
\" C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Payload\\crossgen.exe\"  /Platform_Assemblies_Paths C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Payload;C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Work\\b883f6c8-423d-49c3-be11-0d7517474875\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\IL;C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Work\\b883f6c8-423d-49c3-be11-0d7517474875\\Exec\\tracing\\eventpipe\\buffersize\\buffersize /in buffersize.org /out buffersize.exe
Microsoft (R) CoreCLR Native Image Generator - Version 4.5.30319.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Native image buffersize.exe generated successfully.
 \"C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Payload\\corerun.exe\" buffersize.exe 
TEST STARTING
TEST PASSED!
TEST STARTING
TEST PASSED!

cmdLine:C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Work\\b883f6c8-423d-49c3-be11-0d7517474875\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\buffersize.cmd Timed Out
Test Harness Exitcode is : -100
To run the test:
> set CORE_ROOT=C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Payload
> C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Work\\b883f6c8-423d-49c3-be11-0d7517474875\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\buffersize.cmd
Expected: True
Actual:   False

Stack Trace :

   at tracing_eventpipe._buffersize_buffersize_buffersize_._buffersize_buffersize_buffersize_cmd() in F:\workspace.1\_work\1\s\bin\tests\Windows_NT.x64.Release\TestWrappers\tracing.eventpipe\tracing.eventpipe.XUnitWrapper.cs:line 142

Details:
https://mc.dot.net/#/product/netcore/master/source/official~2Fdotnet~2Fcoreclr~2Frefs~2Fheads~2Fmaster/type/test~2Ffunctional~2Fr2r~2Fcli~2F/build/20190725.2/workItem/PayloadGroup0/analysis/xunit/tracing_eventpipe._buffersize_buffersize_buffersize_~2F_buffersize_buffersize_buffersize_cmd

[josalem]

@janvorli do you have any intuition on what might be going on here? My hunch is that something in the EventPipe client library is failing to unload due to the native components involved in the IPC communication, but I haven't looked at a repro yet.

[janvorli]

I'm not seeing any indication that the test was running using the runincontext tool. Seeing \"C:\\dotnetbuild\\work\\b32ed47f-3a4a-4cd8-99a5-035b9d2db11c\\Payload\\corerun.exe\" buffersize.exe means that it was just pure run of the test exe. If it was ran using the runincontext tool, the runincontext.dll would be in the command line between the corerun and the test exe.

[jorive]

@janvorli This is the log:

Return code:      1
Raw output file:      C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Work\\5095a7a2-9705-4c75-8202-63eb131acfd4\\Exec\\tracing\\eventpipe\\Reports\\tracing.eventpipe\\buffersize\\buffersize\\buffersize.output.txt
Raw output:
BEGIN EXECUTION
call C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Payload\\runincontext.cmd C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Work\\5095a7a2-9705-4c75-8202-63eb131acfd4\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\ buffersize.exe 
TEST STARTING
TEST PASSED!
TEST STARTING
TEST PASSED!
FAILURE: Unload failed

RunInContext FAIL! Exiting with code 213
Expected: 100
Actual: 213
END EXECUTION - FAILED
FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Payload
> C:\\dotnetbuild\\work\\37aa7f0a-0c08-4d89-9a91-6919c4ded4d5\\Work\\5095a7a2-9705-4c75-8202-63eb131acfd4\\Exec\\tracing\\eventpipe\\buffersize\\buffersize\\buffersize.cmd
Expected: True
Actual:   False

[janvorli]

Ah, I've looked only at the most recent log here.
@josalem as for figuring out what's preventing the unload, the easiest way is to set env var RunInContextExtraArgs="/breakafterrun" and then run the test under WinDbg. It will hit a breakpoint after the test is run. Then you'd run !dumpheap -type LoaderAllocator, find the LoaderAllocator instance address from the details it dumps and finally run !gcroot -all the_address_of_the_LoaderAllocator. That will show you the roots that prevent unloading.
There are details on this at https://docs.microsoft.com/en-us/dotnet/standard/assembly/unloadability-howto#debug-unloading-issues

[jorive]

@janvorli We followed your suggestions and ran the commands you specified.

First,

!dumpheap -type LoaderAllocator

         Address               MT     Size
000001b19108b848 00007ffc93b698b8       48     
000001b19108b878 00007ffc93b69b70       24     

Statistics:
              MT    Count    TotalSize Class Name
00007ffc93b69b70        1           24 System.Reflection.LoaderAllocatorScout
00007ffc93b698b8        1           48 System.Reflection.LoaderAllocator
Total 2 objects

Then,

!gcroot -all 000001b19108b878

HandleTable:
    000001b18eec15f8 (pinned handle)
    -> 000001b1a1071038 System.Object[]
    -> 000001b1910a92f0 System.Diagnostics.TraceInternal+TraceProvider
    -> 000001b19108b848 System.Reflection.LoaderAllocator
    -> 000001b19108b878 System.Reflection.LoaderAllocatorScout

Found 1 roots.

The System.Object[] is an array of 1020 objects, that contains the TraceProvider.

...
[709] 000001b1910a92f0
...

!DumpObj /d 000001b1910a92f0

Name:        System.Diagnostics.TraceInternal+TraceProvider
MethodTable: 00007ffc94394398
EEClass:     00007ffc94393fd0
Size:        32(0x20) bytes
File:        S:\github.com\jorive\coreclr\bin\tests\Windows_NT.x64.Checked\Tests\Core_Root\System.Diagnostics.TraceSource.dll
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ffc93ab07b8  40018ba       10       System.Boolean  1 instance                1 _needIndent
00007ffc93af9eb8  40018bb        8        System.String  0 instance 0000000000000000 _indentString
00007ffc939d0cd8  40018b9     1638        System.Object  0   static 000001b1910a9830 s_lock
0000000000000000  40018bc     1640                       0   static 0000000000000000 s_FailCore
0000000000000000  40018bd     1648                       0   static 0000000000000000 s_WriteCore
00007ffc939d0cd8  40018be     1650        System.Object  0   static 000001b1910a9848 s_ForLock

At this point, I do not know where to go (how did this object get there?). Could you please give us some guidance or take a look?

[janvorli]

This is a static variable containing instance of the TraceProvider (the 1020 elements array is array of statics). The TraceProvider instance is created from an assembly loaded into the unloadable context, but stored in a static variable outside of that context. That prevents unloading. I am not sure how that ends up happening. It would be interesting to see the stack trace at which the instance of the TraceProvider is created. That should give us a clue whether it is a problem due to the way the test is run in the unloadable context (=> the test is not compatible with the way we run it and so we should disable it for the runincontext testing) or whether there is some problem with the tracing and unloadability that needs to be fixed.

[jorive]

More information: This is the callstack when Debug.SetProvider(new TraceProvider()); is invoked. This call stores the TraceProvider instance in a static variable.

>	System.Diagnostics.TraceSource.dll!System.Diagnostics.TraceInternal.Listeners.get() Line 66	C#
 	System.Diagnostics.TraceSource.dll!System.Diagnostics.TraceInternal.WriteLine(string message) Line 560	C#
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.Parsers.RegisteredTraceEventParser.TdhEventParser.ParseFields(int startField, int numFields)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.Parsers.RegisteredTraceEventParser.TdhEventParser.ParseEventMetaData()	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.Parsers.RegisteredTraceEventParser.TryLookupWorker(Microsoft.Diagnostics.Tracing.TraceEvent unknownEvent, System.Collections.Generic.Dictionary<Microsoft.Diagnostics.Tracing.Parsers.MapKey, System.Collections.Generic.IDictionary<long, string>> mapTable)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.Parsers.ExternalTraceEventParser..ctor.AnonymousMethod__0_0(Microsoft.Diagnostics.Tracing.TraceEvent unknown)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.TraceEventDispatcher.Lookup(Microsoft.Diagnostics.Tracing.TraceEventNativeMethods.EVENT_RECORD* eventRecord)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.EventPipeEventSource.DispatchEventRecord(Microsoft.Diagnostics.Tracing.TraceEventNativeMethods.EVENT_RECORD* eventRecord)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.EventPipeEventSource.EventCache_OnEvent(ref Microsoft.Diagnostics.Tracing.EventPipeEventHeader header)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.EventPipe.EventCache.SortAndDispatch(long stopTimestamp)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.EventPipe.EventCache.ProcessEventBlock(byte[] eventBlockData)	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.EventPipeBlock.FromStream(FastSerialization.Deserializer deserializer)	Unknown
 	Microsoft.Diagnostics.FastSerialization.dll!FastSerialization.Deserializer.ReadObjectDefinition(FastSerialization.Tags tag, FastSerialization.StreamLabel objectLabel)	Unknown
 	Microsoft.Diagnostics.FastSerialization.dll!FastSerialization.Deserializer.ReadObject()	Unknown
 	Microsoft.Diagnostics.Tracing.TraceEvent.dll!Microsoft.Diagnostics.Tracing.EventPipeEventSource.Process()	Unknown
 	common.dll!Tracing.Tests.Common.IpcTraceTest.Validate.AnonymousMethod__1() Line 178	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.InnerInvoke() Line 2449	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task..cctor.AnonymousMethod__274_0(object obj) Line 2428	C#
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(System.Threading.Thread threadPoolThread, System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 289	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot, System.Threading.Thread threadPoolThread) Line 2389	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread threadPoolThread) Line 2327	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteFromThreadPool(System.Threading.Thread threadPoolThread) Line 2312	C#
 	System.Private.CoreLib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch() Line 663	C#
 	System.Private.CoreLib.dll!System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() Line 29	C#

[janvorli]

I understand the issue now. The Debug.SetProvider is in System.Private.CoreLib that is loaded into the default context. But the Microsoft.Diagnostics.TraceSource.dll was loaded into the testing unloadable context. So we've created an instance of the TraceProvider type from that assembly living in the unloadable context and stored it into a static variable in the default context.

We should mark the test as incompatible with the runincontext testing. In real world scenarios, the System.Diagnostics.TraceSource.dll which is a part of the runtime would not be loaded into the unloadable context.
You can do it by adding <UnloadabilityIncompatible>true</UnloadabilityIncompatible> into the PropertyGroup in the .csproj of the test.