From 0eaa21fac392b3cf24123acc44d51e67346dd9b4 Mon Sep 17 00:00:00 2001 From: David Wrighton Date: Wed, 14 Jul 2021 18:04:59 -0700 Subject: [PATCH 1/4] Add more logging and flushes to name_with_pid in hopes of understanding why it fails in CI --- .../eventpipe/complus_config/name_config_with_pid.cs | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs b/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs index 7cca9d64320bb4..c163c2e566bb31 100644 --- a/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs +++ b/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs @@ -11,10 +11,17 @@ class NameConfigWithPid { static int Main(string[] args) { + if (args.Length == 0) + Console.WriteLine("No Args"); + else + Console.WriteLine($"args[0] = `{args[0]}`"); + if (args.Length > 0 && args[0] == "waitforinput") { Console.Error.WriteLine("WaitingForInput in ErrorStream"); Console.WriteLine("WaitingForInput"); + Console.Error.Flush(); + Console.Out.Flush(); Console.ReadLine(); return 100; } @@ -50,13 +57,18 @@ static int Main(string[] args) process.StartInfo.Environment.Add("COMPlus_EventPipeConfig", "Microsoft-Windows-DotNETRuntime:4c14fccbd:4"); process.StartInfo.Environment.Add("COMPlus_EventPipeOutputPath", outputPathPattern); + Console.WriteLine($"Starting process '{process.StartInfo.FileName}' '{process.StartInfo.Arguments}'"); + Console.Out.Flush(); process.Start(); process.StandardError.ReadLine(); + Console.WriteLine($"After readline'"); + Console.Out.Flush(); uint pid = (uint)process.Id; string expectedPath = outputPathPattern.Replace("{pid}", pid.ToString()); process.StandardInput.WriteLine("input"); + process.StandardInput.Flush(); process.WaitForExit(); if (!File.Exists(expectedPath)) { From dc718894bbdc1fc1f2be1a613dce2996475737c8 Mon Sep 17 00:00:00 2001 From: David Wrighton Date: Thu, 15 Jul 2021 17:15:26 -0700 Subject: [PATCH 2/4] Add fix and update test to be even more verbose --- src/coreclr/binder/bindertracing.cpp | 7 ++++++- .../complus_config/name_config_with_pid.cs | 17 ++++++++++++++--- 2 files changed, 20 insertions(+), 4 deletions(-) diff --git a/src/coreclr/binder/bindertracing.cpp b/src/coreclr/binder/bindertracing.cpp index 29ba819ee6c9e7..ca74514d305c6e 100644 --- a/src/coreclr/binder/bindertracing.cpp +++ b/src/coreclr/binder/bindertracing.cpp @@ -196,6 +196,8 @@ bool BinderTracing::IsEnabled() namespace BinderTracing { + static thread_local bool t_AssemblyLoadStartInProgress = false; + AssemblyBindOperation::AssemblyBindOperation(AssemblySpec *assemblySpec, const WCHAR *assemblyPath) : m_bindRequest { assemblySpec, nullptr, assemblyPath } , m_populatedBindRequest { false } @@ -209,6 +211,7 @@ namespace BinderTracing if (!BinderTracing::IsEnabled() || ShouldIgnoreBind()) return; + t_AssemblyLoadStartInProgress = true; PopulateBindRequest(m_bindRequest); m_populatedBindRequest = true; FireAssemblyLoadStart(m_bindRequest); @@ -218,6 +221,8 @@ namespace BinderTracing { if (BinderTracing::IsEnabled() && !ShouldIgnoreBind()) { + t_AssemblyLoadStartInProgress = false; + // Make sure the bind request is populated. Tracing may have been enabled mid-bind. if (!m_populatedBindRequest) PopulateBindRequest(m_bindRequest); @@ -246,7 +251,7 @@ namespace BinderTracing // ActivityTracker or EventSource may have triggered the system satellite load. // Don't track system satellite binding to avoid potential infinite recursion. - m_ignoreBind = m_bindRequest.AssemblySpec->IsCoreLibSatellite(); + m_ignoreBind = m_bindRequest.AssemblySpec->IsCoreLibSatellite() || t_AssemblyLoadStartInProgress; m_checkedIgnoreBind = true; return m_ignoreBind; } diff --git a/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs b/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs index c163c2e566bb31..d94f8cc49fb074 100644 --- a/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs +++ b/src/tests/tracing/eventpipe/complus_config/name_config_with_pid.cs @@ -38,7 +38,8 @@ static int Main(string[] args) return 100; } - string corerun = Path.Combine(Environment.GetEnvironmentVariable("CORE_ROOT"), "corerun"); + string coreRoot = Environment.GetEnvironmentVariable("CORE_ROOT"); + string corerun = Path.Combine(coreRoot, "corerun"); if (OperatingSystem.IsWindows()) corerun = corerun + ".exe"; @@ -56,13 +57,21 @@ static int Main(string[] args) process.StartInfo.Environment.Add("COMPlus_EnableEventPipe", "1"); process.StartInfo.Environment.Add("COMPlus_EventPipeConfig", "Microsoft-Windows-DotNETRuntime:4c14fccbd:4"); process.StartInfo.Environment.Add("COMPlus_EventPipeOutputPath", outputPathPattern); + process.StartInfo.Environment.Add("CORE_ROOT", coreRoot); Console.WriteLine($"Starting process '{process.StartInfo.FileName}' '{process.StartInfo.Arguments}'"); Console.Out.Flush(); process.Start(); - process.StandardError.ReadLine(); - Console.WriteLine($"After readline'"); + string readFromTargetProcess = process.StandardError.ReadLine(); + Console.WriteLine($"Readline '{readFromTargetProcess}'"); + if (readFromTargetProcess != "WaitingForInput in ErrorStream") + { + Console.WriteLine($"Child process terminating"); + Thread.Sleep(10000); + process.Kill(); + Console.WriteLine($"Child process terminated"); + } Console.Out.Flush(); uint pid = (uint)process.Id; string expectedPath = outputPathPattern.Replace("{pid}", pid.ToString()); @@ -70,6 +79,8 @@ static int Main(string[] args) process.StandardInput.WriteLine("input"); process.StandardInput.Flush(); process.WaitForExit(); + + Console.WriteLine($"StdErr ReadToEnd from child process '{process.StandardError.ReadToEnd()}'"); if (!File.Exists(expectedPath)) { Console.WriteLine($"{expectedPath} not found"); From dcaa74df1ebbd84e125f93ea42d9e2dea3e8f47a Mon Sep 17 00:00:00 2001 From: David Wrighton Date: Thu, 15 Jul 2021 21:38:21 -0700 Subject: [PATCH 3/4] Limit nested bind reporting prevention to CoreLib. --- src/coreclr/binder/bindertracing.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/coreclr/binder/bindertracing.cpp b/src/coreclr/binder/bindertracing.cpp index ca74514d305c6e..7c26266ebf9e1b 100644 --- a/src/coreclr/binder/bindertracing.cpp +++ b/src/coreclr/binder/bindertracing.cpp @@ -251,7 +251,7 @@ namespace BinderTracing // ActivityTracker or EventSource may have triggered the system satellite load. // Don't track system satellite binding to avoid potential infinite recursion. - m_ignoreBind = m_bindRequest.AssemblySpec->IsCoreLibSatellite() || t_AssemblyLoadStartInProgress; + m_ignoreBind = m_bindRequest.AssemblySpec->IsCoreLibSatellite() || (t_AssemblyLoadStartInProgress && m_bindRequest.AssemblySpec->IsCoreLib()); m_checkedIgnoreBind = true; return m_ignoreBind; } From b9317817ce1cd25613bca44f6948718e204c9bb5 Mon Sep 17 00:00:00 2001 From: David Wrighton Date: Fri, 16 Jul 2021 13:39:52 -0700 Subject: [PATCH 4/4] Address code review feedback --- src/coreclr/binder/bindertracing.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/coreclr/binder/bindertracing.cpp b/src/coreclr/binder/bindertracing.cpp index 7c26266ebf9e1b..801226e935d005 100644 --- a/src/coreclr/binder/bindertracing.cpp +++ b/src/coreclr/binder/bindertracing.cpp @@ -249,9 +249,9 @@ namespace BinderTracing if (m_checkedIgnoreBind) return m_ignoreBind; - // ActivityTracker or EventSource may have triggered the system satellite load. - // Don't track system satellite binding to avoid potential infinite recursion. - m_ignoreBind = m_bindRequest.AssemblySpec->IsCoreLibSatellite() || (t_AssemblyLoadStartInProgress && m_bindRequest.AssemblySpec->IsCoreLib()); + // ActivityTracker or EventSource may have triggered the system satellite load, or load of System.Private.CoreLib + // Don't track such bindings to avoid potential infinite recursion. + m_ignoreBind = t_AssemblyLoadStartInProgress && (m_bindRequest.AssemblySpec->IsCoreLib() || m_bindRequest.AssemblySpec->IsCoreLibSatellite()); m_checkedIgnoreBind = true; return m_ignoreBind; }