BinderTracingTest.ResolutionFlow.cmd timed out

[safern]

    Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd [FAIL]
      
      
      
      
      
      cmdLine:D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd Timed Out
      
      Return code:      -100
      Raw output file:      D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\Reports\Loader.binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.output.txt
      Raw output:
      BEGIN EXECUTION
       "D:\h\w\B9770A31\p\corerun.exe" BinderTracingTest.ResolutionFlow.dll 
      Launching process for AppDomainAssemblyResolveEvent_Exception...
      Running AppDomainAssemblyResolveEvent_Exception...
      
      Launching process for LoadFromAssemblyPath_FoundInAppPath...
      Running LoadFromAssemblyPath_FoundInAppPath...
      
      Launching process for LoadFromAssemblyPath_FoundInLoadContext_DifferentMvid...
      Running LoadFromAssemblyPath_FoundInLoadContext_DifferentMvid...
      
      Launching process for LoadFromAssemblyPath_FoundInAppPath_IncompatibleVersion...
      Running LoadFromAssemblyPath_FoundInAppPath_IncompatibleVersion...
      
      Running AssemblyLoadContextResolving_ReturnNull...
      
      cmdLine:D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd Timed Out
      Test Harness Exitcode is : -100
      To run the test:
      > set CORE_ROOT=D:\h\w\B9770A31\p
      > D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd
      Expected: True
      Actual:   False
      Stack Trace:
        F:\workspace\_work\1\s\artifacts\tests\coreclr\Windows_NT.arm.Checked\TestWrappers\Loader.binding\Loader.binding.XUnitWrapper.cs(237,0): at Loader_binding._tracing_BinderTracingTest_ResolutionFlow_BinderTracingTest_ResolutionFlow_._tracing_BinderTracingTest_ResolutionFlow_BinderTracingTest_ResolutionFlow_cmd()
      Output:
        
        
        
        
        
        cmdLine:D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd Timed Out
        
        Return code:      -100
        Raw output file:      D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\Reports\Loader.binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.output.txt
        Raw output:
        BEGIN EXECUTION
         "D:\h\w\B9770A31\p\corerun.exe" BinderTracingTest.ResolutionFlow.dll 
        Launching process for AppDomainAssemblyResolveEvent_Exception...
        Running AppDomainAssemblyResolveEvent_Exception...
        
        Launching process for LoadFromAssemblyPath_FoundInAppPath...
        Running LoadFromAssemblyPath_FoundInAppPath...
        
        Launching process for LoadFromAssemblyPath_FoundInLoadContext_DifferentMvid...
        Running LoadFromAssemblyPath_FoundInLoadContext_DifferentMvid...
        
        Launching process for LoadFromAssemblyPath_FoundInAppPath_IncompatibleVersion...
        Running LoadFromAssemblyPath_FoundInAppPath_IncompatibleVersion...
        
        Running AssemblyLoadContextResolving_ReturnNull...
        
        cmdLine:D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd Timed Out
        Test Harness Exitcode is : -100
        To run the test:
        > set CORE_ROOT=D:\h\w\B9770A31\p
        > D:\h\w\B9770A31\w\AD170A04\e\Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd

This was on Windows arm

https://dev.azure.com/dnceng/public/_build/results?buildId=662529&view=logs&j=3ce1ffe6-2daf-5d48-23b6-56961b8285e2&t=e1bc0efe-88b5-592d-ae74-0ec82e3852af&l=38

cc: @jashook who would be the right person to look into this?

Runfo Tracking Issue: Runtime failures in BinderTracingTest.ResolutionFlow

Build	Definition	Kind	Run Name	Console	Core Dump	Test Results	Run Client
1268713	runtime	PR 54580	CoreCLR Linux x64 Checked @ Ubuntu.1804.Amd64.Open	console.log			runclient.py
1268713	runtime	PR 54580	CoreCLR Linux x64 Checked no_tiered_compilation @ Ubuntu.1804.Amd64.Open	console.log			runclient.py

Build Result Summary

Day Hit Count	Week Hit Count	Month Hit Count
0	0	1

[vitek-karas]

/cc @elinor-fung @vitek-karas

[am11]

Failed again in #37254.
console log

[safern]

Failed again in: https://helix.dot.net/api/2019-06-17/jobs/7f75d67d-78f2-485f-b900-2a1e13f121d1/workitems/PayloadGroup0/console

[jashook]

Is the correct area assembly loader?

[ghost]

Tagging subscribers to this area: @vitek-karas, @agocke
Notify danmosemsft if you want to be subscribed.

[vitek-karas]

Can we determine when was the last time we saw this failure? @elinor-fung added some fixes relatively recently to the binder tracing tests - maybe it has already been fixed.

[AntonLapounov]

This test failed in my PR (CoreCLR Pri0 Runtime Tests Run Windows_NT arm checked).
https://helix.dot.net/api/2019-06-17/jobs/97e4a4cc-c6f6-4393-87cd-50b9aabe3ca2/workitems/PayloadGroup0/console

    Loader\binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.cmd [FAIL]
      Return code:      1
      Raw output file:      D:\h\w\B4F40A09\w\B07D094D\e\Loader\binding\Reports\Loader.binding\tracing\BinderTracingTest.ResolutionFlow\BinderTracingTest.ResolutionFlow.output.txt
      Raw output:
      BEGIN EXECUTION
       "D:\h\w\B4F40A09\p\corerun.exe" BinderTracingTest.ResolutionFlow.dll 
      [1:05:59 PM] Launching process for AppDomainAssemblyResolveEvent_Exception...
      [1:05:59 PM] Running AppDomainAssemblyResolveEvent_Exception...
      
      [1:06:00 PM] Launching process for LoadFromAssemblyPath_FoundInAppPath...
      [1:06:00 PM] Running LoadFromAssemblyPath_FoundInAppPath...
      
      [1:06:01 PM] Launching process for LoadFromAssemblyPath_FoundInLoadContext_DifferentMvid...
      [1:06:02 PM] Running LoadFromAssemblyPath_FoundInLoadContext_DifferentMvid...
      
      [1:06:02 PM] Launching process for LoadFromAssemblyPath_FoundInAppPath_IncompatibleVersion...
      [1:06:03 PM] Running LoadFromAssemblyPath_FoundInAppPath_IncompatibleVersion...
      
      [1:06:03 PM] Running AssemblyLoadContextResolving_ReturnNull...
      Test AssemblyLoadContextResolving_ReturnNull failed: System.AggregateException: One or more errors occurred. (An error occurred when writing to a listener.)
       ---> System.Diagnostics.Tracing.EventSourceException: An error occurred when writing to a listener.
       ---> System.ArgumentNullException: Value cannot be null. (Parameter 'source')
         at System.Linq.ThrowHelper.ThrowArgumentNullException(ExceptionArgument argument) in /_/src/libraries/System.Linq/src/System/Linq/ThrowHelper.cs:line 12
         at System.Linq.Enumerable.Any[TSource](IEnumerable`1 source, Func`2 predicate) in /_/src/libraries/System.Linq/src/System/Linq/AnyAll.cs:line 51
         at BinderTracingTests.BinderEventListener.IsLoadToTrack(String name) in /Users/runner/work/1/s/src/tests/Loader/binding/tracing/BinderEventListener.cs:line 361
         at BinderTracingTests.BinderEventListener.OnEventWritten(EventWrittenEventArgs data) in /Users/runner/work/1/s/src/tests/Loader/binding/tracing/BinderEventListener.cs:line 343
         at System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(Int32 eventId, EventWrittenEventArgs eventCallbackArgs)
         --- End of inner exception stack trace ---
         at System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(Int32 eventId, EventWrittenEventArgs eventCallbackArgs)
         at System.Diagnostics.Tracing.EventSource.WriteToAllListeners(Int32 eventId, UInt32* osThreadId, DateTime* timeStamp, Guid* activityID, Guid* childActivityID, Object[] args)
         at System.Diagnostics.Tracing.EventPipeEventDispatcher.DispatchEventsToEventListeners()
         at System.Threading.Tasks.Task.InnerInvoke()
         at System.Threading.Tasks.Task.<>c.<.cctor>b__277_0(Object obj)
         at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      --- End of stack trace from previous location ---
         at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
         at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
         --- End of inner exception stack trace ---
         at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
         at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
         at System.Threading.Tasks.Task.Wait()
         at System.Diagnostics.Tracing.EventPipeEventDispatcher.StopDispatchTask()
         at System.Diagnostics.Tracing.EventPipeEventDispatcher.CommitDispatchConfiguration()
         at System.Diagnostics.Tracing.EventPipeEventDispatcher.RemoveEventListener(EventListener listener)
         at System.Diagnostics.Tracing.EventListener.RemoveReferencesToListenerInEventSources(EventListener listenerToRemove)
         at System.Diagnostics.Tracing.EventListener.Dispose()
         at BinderTracingTests.BinderTracingTest.RunSingleTest(MethodInfo method) in /Users/runner/work/1/s/src/tests/Loader/binding/tracing/BinderTracingTest.cs:line 173
      Expected: 100
      Actual: 101
      END EXECUTION - FAILED
      FAILED

[vitek-karas]

The second failure makes no sense to me:
It's failing because the this.loadsToTrack is null here:

runtime/src/tests/Loader/binding/tracing/BinderEventListener.cs

Line 361 in 9a5ef96

return this.loadsToTrack.Any(n => n.Equals(name, StringComparison.InvariantCultureIgnoreCase));

But that variable is initialized to the .ctor argument in the .ctor here:

runtime/src/tests/Loader/binding/tracing/BinderEventListener.cs

Line 170 in 9a5ef96

this.loadsToTrack = loadsToTrack;

This is the only .ctor the class has. The .ctor is called from just one place here:

runtime/src/tests/Loader/binding/tracing/BinderTracingTest.cs

Line 169 in 9a5ef96

using (var listener = new BinderEventListener(loadsToTrack))

That place passes the argument as a value returned by either new string[] or Union call, neither should ever return null. It's also not an initialization timing issue, since the failure occurs during Dispose which is called only after the initialization is fully done (via a using statement).

[jkotas]

Failed in #41757

[jaredpar]

Note this failed again today. I've made this a live issue so failures will be tracked in the main body.

[janvorli]

I keep hitting the timeout locally on my macOS device consistently.

[hoyosjs]

@sywhang and I took a look at this. It is a product issue that can cause deadlocks. It can hit any test that uses tracing (like BinderTracingTest.Basic and BinderTracingTest.ResolutionFlow do).