Skip to content

Commit

Permalink
Add more verbose logging (dotnet#37089)
Browse files Browse the repository at this point in the history
* log out stdout/stderr of subprocess
* instead of using Process.Kill, gracefully exit
  • Loading branch information
John Salem authored May 29, 2020
1 parent cacebda commit 4a2d96c
Showing 1 changed file with 49 additions and 3 deletions.
52 changes: 49 additions & 3 deletions src/coreclr/tests/src/tracing/eventpipe/reverse/reverse.cs
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
using System.Reflection;
using Microsoft.Diagnostics.Tools.RuntimeClient;
using Tracing.Tests.Common;
using System.Text;
using System.Threading;
using System.IO;
using Microsoft.Diagnostics.Tracing;
Expand Down Expand Up @@ -45,25 +46,68 @@ public static async Task RunSubprocess(string serverName, Func<Task> beforeExecu
if (beforeExecution != null)
await beforeExecution();

var stdoutSb = new StringBuilder();
var stderrSb = new StringBuilder();

process.StartInfo.UseShellExecute = false;
process.StartInfo.CreateNoWindow = true;
process.StartInfo.Environment.Add("DOTNET_DiagnosticsMonitorAddress", serverName);
process.StartInfo.FileName = Process.GetCurrentProcess().MainModule.FileName;
process.StartInfo.Arguments = new Uri(Assembly.GetExecutingAssembly().CodeBase).LocalPath + " 0";
process.StartInfo.RedirectStandardOutput = true;
process.StartInfo.RedirectStandardInput = true;
process.StartInfo.RedirectStandardError = true;

Logger.logger.Log($"running sub-process: {process.StartInfo.FileName} {process.StartInfo.Arguments}");

process.OutputDataReceived += new DataReceivedEventHandler((s,e) =>
{
if (!string.IsNullOrEmpty(e.Data))
{
stdoutSb.Append($"\n\t{(DateTime.Now - process.StartTime).TotalSeconds,5:f1}s: {e.Data}");
}
});

process.ErrorDataReceived += new DataReceivedEventHandler((s,e) =>
{
if (!string.IsNullOrEmpty(e.Data))
{
stderrSb.Append($"\n\t{(DateTime.Now - process.StartTime).TotalSeconds,5:f1}s: {e.Data}");
}
});

bool fSuccess = process.Start();
StreamWriter subprocesssStdIn = process.StandardInput;
process.BeginOutputReadLine();
process.BeginErrorReadLine();
Logger.logger.Log($"subprocess started: {fSuccess}");
Logger.logger.Log($"subprocess PID: {process.Id}");

while (!EventPipeClient.ListAvailablePorts().Contains(process.Id))
{
Logger.logger.Log($"Standard Diagnostics Server connection not created yet -> try again in 100 ms");
await Task.Delay(100);
}

try
{
if (duringExecution != null)
await duringExecution(process.Id);
Logger.logger.Log($"Sending 'exit' to subprocess stdin");
subprocesssStdIn.WriteLine("exit");
subprocesssStdIn.Close();
if (!process.WaitForExit(5000))
{
Logger.logger.Log("Subprocess didn't exit in 5 seconds!");
throw new TimeoutException("Subprocess didn't exit in 5 seconds");
}
Logger.logger.Log($"SubProcess exited - Exit code: {process.ExitCode}");
Logger.logger.Log($"Subprocess stdout: {stdoutSb.ToString()}");
Logger.logger.Log($"Subprocess stderr: {stderrSb.ToString()}");
}
finally
catch (Exception e)
{
Logger.logger.Log($"Calling process.Kill()");
process.Kill();
}

Expand Down Expand Up @@ -309,8 +353,10 @@ public static async Task<int> Main(string[] args)
{
if (args.Length >= 1)
{
await Task.Delay(TimeSpan.FromMinutes(10)); // will be killed in test
return 1;
Console.Out.WriteLine("Subprocess started! Waiting for input...");
var input = Console.In.ReadLine(); // will block until data is sent across stdin
Console.Out.WriteLine($"Received '{input}'. Exiting...");
return 0;
}

bool fSuccess = true;
Expand Down

0 comments on commit 4a2d96c

Please sign in to comment.