Skip to content

Commit

Permalink
[Test] Reverse EventPipe test improvements (#38474)
Browse files Browse the repository at this point in the history 
* generalize clean env check

* Remove in-test timeouts
* timeouts will show up as test failures and trigger dump collection
* Add notification of and diagnostics on early subprocess exit

* move pathologic test to outer loop

* Turn back on other reverse tests

* Respond to PR feedback
  • Loading branch information
John Salem authored Jul 3, 2020
1 parent ff1ea09 commit 7c891ca
Show file tree
Hide file tree
Showing 8 changed files with 211 additions and 114 deletions.
3 changes: 0 additions & 3 deletions src/coreclr/tests/issues.targets
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,9 +2,6 @@
<Project DefaultTargets = "GetListOfTestCmds" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
<!-- All OS/Arch/Runtime excludes -->
<ItemGroup Condition="'$(XunitTestBinBase)' != ''">
<ExcludeList Include="$(XunitTestBinBase)/tracing/eventpipe/reverse/reverse/*">
<Issue>https://github.com/dotnet/runtime/issues/38156</Issue>
</ExcludeList>
<ExcludeList Include="$(XunitTestBinBase)/tracing/tracecontrol/tracecontrol/*">
<Issue>https://github.com/dotnet/runtime/issues/11204</Issue>
</ExcludeList>
Expand Down
75 changes: 42 additions & 33 deletions src/coreclr/tests/src/tracing/eventpipe/common/IpcTraceTest.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -186,7 +186,7 @@ private int Validate()
emptyConcurrentDictionary["foo"] = "bar";
var __count = emptyConcurrentDictionary.Count;

var isClean = EnsureCleanEnvironment();
var isClean = IpcTraceTest.EnsureCleanEnvironment();
if (!isClean)
return -1;
// CollectTracing returns before EventPipe::Enable has returned, so the
Expand Down Expand Up @@ -339,53 +339,62 @@ private int Validate()
// run into these zombie pipes if there are failures over time.
// Note: Windows has some guarantees about named pipes not living longer
// the process that created them, so we don't need to check on that platform.
private bool EnsureCleanEnvironment()
static public bool EnsureCleanEnvironment()
{
if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows))
{
Logger.logger.Log("Validating clean environment...");
// mimic the RuntimeClient's code for finding OS Transports
IEnumerable<FileInfo> ipcPorts = Directory.GetFiles(Path.GetTempPath())
.Select(namedPipe => new FileInfo(namedPipe))
.Where(input => Regex.IsMatch(input.Name, $"^dotnet-diagnostic-{System.Diagnostics.Process.GetCurrentProcess().Id}-(\\d+)-socket$"));

if (ipcPorts.Count() > 1)
Func<(IEnumerable<IGrouping<int,FileInfo>>, List<int>)> getPidsAndSockets = () =>
{
Logger.logger.Log($"Found {ipcPorts.Count()} OS transports for pid {System.Diagnostics.Process.GetCurrentProcess().Id}:");
foreach (var match in ipcPorts)
{
Logger.logger.Log($"\t{match.Name}");
}

// Get everything _except_ the newest pipe
var duplicates = ipcPorts.OrderBy(fileInfo => fileInfo.CreationTime.Ticks).SkipLast(1);
foreach (var duplicate in duplicates)
{
Logger.logger.Log($"Attempting to delete the oldest pipe: {duplicate.FullName}");
duplicate.Delete(); // should throw if we can't delete and be caught in Validate
Logger.logger.Log($"Deleted");
}
IEnumerable<IGrouping<int,FileInfo>> currentIpcs = Directory.GetFiles(Path.GetTempPath(), "dotnet-diagnostic*")
.Select(filename => new { pid = int.Parse(Regex.Match(filename, @"dotnet-diagnostic-(?<pid>\d+)").Groups["pid"].Value), fileInfo = new FileInfo(filename) })
.GroupBy(fileInfos => fileInfos.pid, fileInfos => fileInfos.fileInfo);
List<int> currentPids = System.Diagnostics.Process.GetProcesses().Select(pid => pid.Id).ToList();
return (currentIpcs, currentPids);
};

var afterIpcPorts = Directory.GetFiles(Path.GetTempPath())
.Select(namedPipe => new FileInfo(namedPipe))
.Where(input => Regex.IsMatch(input.Name, $"^dotnet-diagnostic-{System.Diagnostics.Process.GetCurrentProcess().Id}-(\\d+)-socket$"));
var (currentIpcs, currentPids) = getPidsAndSockets();

if (afterIpcPorts.Count() == 1)
foreach (var ipc in currentIpcs)
{
if (!currentPids.Contains(ipc.Key))
{
return true;
foreach (FileInfo fi in ipc)
{
Logger.logger.Log($"Attempting to delete the zombied pipe: {fi.FullName}");
fi.Delete();
Logger.logger.Log($"Deleted");
}
}
else
{
Logger.logger.Log($"Unable to clean the environment. The following transports are on the system:");
foreach(var transport in afterIpcPorts)
if (ipc.Count() > 1)
{
Logger.logger.Log($"\t{transport.FullName}");
// delete zombied pipes except newest which is owned
var duplicates = ipc.OrderBy(fileInfo => fileInfo.CreationTime.Ticks).SkipLast(1);
foreach (FileInfo fi in duplicates)
{
Logger.logger.Log($"Attempting to delete the zombied pipe: {fi.FullName}");
fi.Delete();
}
}
}
}

// validate we cleaned everything up
(currentIpcs, currentPids) = getPidsAndSockets();

// if there are pipes for processses that don't exist anymore,
// or a process has multiple pipes, we failed.
foreach (IGrouping<int,FileInfo> group in currentIpcs)
{
if (!currentPids.Contains(group.Key) || group.Count() > 1)
{
Logger.logger.Log("Environment is dirty.");
return false;
}
}
Logger.logger.Log("Environment was clean.");
return true;
Logger.logger.Log("Environment is clean.");

}

return true;
Expand Down
17 changes: 15 additions & 2 deletions src/coreclr/tests/src/tracing/eventpipe/common/IpcUtils.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -92,6 +92,7 @@ public static async Task<bool> RunSubprocess(Assembly currentAssembly, Dictionar
}
});

process.EnableRaisingEvents = true;
fSuccess &= process.Start();
if (!fSuccess)
throw new Exception("Failed to start subprocess");
Expand All @@ -101,6 +102,18 @@ public static async Task<bool> RunSubprocess(Assembly currentAssembly, Dictionar
Logger.logger.Log($"subprocess started: {fSuccess}");
Logger.logger.Log($"subprocess PID: {process.Id}");

bool fGotToEnd = false;
process.Exited += (s, e) =>
{
Logger.logger.Log("================= Subprocess Exited =================");
if (!fGotToEnd)
{
Logger.logger.Log($"- Exit code: {process.ExitCode}");
Logger.logger.Log($"Subprocess stdout: {stdoutSb.ToString()}");
Logger.logger.Log($"Subprocess stderr: {stderrSb.ToString()}");
}
};

while (!EventPipeClient.ListAvailablePorts().Contains(process.Id))
{
Logger.logger.Log($"Standard Diagnostics Server connection not created yet -> try again in 100 ms");
Expand All @@ -111,13 +124,13 @@ public static async Task<bool> RunSubprocess(Assembly currentAssembly, Dictionar
{
if (duringExecution != null)
await duringExecution(process.Id);
fGotToEnd = true;
Logger.logger.Log($"Sending 'exit' to subprocess stdin");
subprocesssStdIn.WriteLine("exit");
subprocesssStdIn.Close();
if (!process.WaitForExit(5000))
while (!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}");
}
Expand Down
12 changes: 7 additions & 5 deletions src/coreclr/tests/src/tracing/eventpipe/pauseonstart/pauseonstart.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,7 @@ public static async Task<bool> TEST_RuntimeResumesExecutionWithCommand()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

return fSuccess;
}
Expand Down Expand Up @@ -90,7 +90,7 @@ public static async Task<bool> TEST_TracesHaveRelevantEvents()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

memoryStream.Seek(0, SeekOrigin.Begin);
using var source = new EventPipeEventSource(memoryStream);
Expand Down Expand Up @@ -164,7 +164,7 @@ public static async Task<bool> TEST_MultipleSessionsCanBeStartedWhilepaused()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

int nStartupEventsSeen = 0;

Expand Down Expand Up @@ -256,7 +256,7 @@ public static async Task<bool> TEST_CanStartAndStopSessionWhilepaused()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

return fSuccess;
}
Expand Down Expand Up @@ -301,7 +301,7 @@ public static async Task<bool> TEST_DisabledCommandsError()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

return fSuccess;
}
Expand All @@ -317,6 +317,8 @@ public static async Task<int> Main(string[] args)
}

bool fSuccess = true;
if (!IpcTraceTest.EnsureCleanEnvironment())
return -1;
IEnumerable<MethodInfo> tests = typeof(PauseOnStartValidation).GetMethods().Where(mi => mi.Name.StartsWith("TEST_"));
foreach (var test in tests)
{
Expand Down
83 changes: 13 additions & 70 deletions src/coreclr/tests/src/tracing/eventpipe/reverse/reverse.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -20,10 +20,6 @@ namespace Tracing.Tests.ReverseValidation
{
public class ReverseValidation
{
// The runtime will do an exponential falloff by a factor of 1.25 starting at 10ms with a max of 500ms
// We can time tests out after waiting 30s which should have sufficient attempts
private static int _maxPollTimeMS = 30_000;

public static async Task<bool> TEST_RuntimeIsResilientToServerClosing()
{
bool fSuccess = true;
Expand All @@ -38,18 +34,18 @@ public static async Task<bool> TEST_RuntimeIsResilientToServerClosing()
},
duringExecution: async (_) =>
{
var ad1 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
var ad1 = await ReverseServer.CreateServerAndReceiveAdvertisement(serverName);
Logger.logger.Log(ad1.ToString());
var ad2 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
var ad2 = await ReverseServer.CreateServerAndReceiveAdvertisement(serverName);
Logger.logger.Log(ad2.ToString());
var ad3 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
var ad3 = await ReverseServer.CreateServerAndReceiveAdvertisement(serverName);
Logger.logger.Log(ad3.ToString());
var ad4 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
var ad4 = await ReverseServer.CreateServerAndReceiveAdvertisement(serverName);
Logger.logger.Log(ad4.ToString());
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

return fSuccess;
}
Expand All @@ -69,12 +65,12 @@ public static async Task<bool> TEST_RuntimeConnectsToExistingServer()
},
duringExecution: async (_) =>
{
IpcAdvertise advertise = await Utils.WaitTillTimeout(advertiseTask, TimeSpan.FromMilliseconds(_maxPollTimeMS));
IpcAdvertise advertise = await advertiseTask;
Logger.logger.Log(advertise.ToString());
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

return fSuccess;
}
Expand Down Expand Up @@ -128,7 +124,7 @@ public static async Task<bool> TEST_CanConnectServerAndClientAtSameTime()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;
server.Shutdown();

return fSuccess;
Expand Down Expand Up @@ -168,7 +164,7 @@ public static async Task<bool> TEST_ServerWorksIfClientDoesntAccept()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;
server.Shutdown();

return true;
Expand Down Expand Up @@ -210,67 +206,12 @@ public static async Task<bool> TEST_ServerIsResilientToNoBufferAgent()
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;
server.Shutdown();

return fSuccess;
}

public static async Task<bool> TEST_ReverseConnectionCanRecycleWhileTracing()
{
bool fSuccess = true;
string serverName = ReverseServer.MakeServerAddress();
Logger.logger.Log($"Server name is '{serverName}'");
Task<bool> subprocessTask = Utils.RunSubprocess(
currentAssembly: Assembly.GetExecutingAssembly(),
environment: new Dictionary<string,string>
{
{ Utils.DiagnosticsMonitorAddressEnvKey, serverName },
{ Utils.DiagnosticsMonitorPauseOnStartEnvKey, "0" }
},
duringExecution: async (int pid) =>
{
Task regularTask = Task.Run(async () =>
{
var config = new SessionConfiguration(
circularBufferSizeMB: 1000,
format: EventPipeSerializationFormat.NetTrace,
providers: new List<Provider> {
new Provider("Microsoft-DotNETCore-SampleProfiler")
});
Logger.logger.Log("Starting EventPipeSession over standard connection");
using Stream stream = EventPipeClient.CollectTracing(pid, config, out var sessionId);
Logger.logger.Log($"Started EventPipeSession over standard connection with session id: 0x{sessionId:x}");
using var source = new EventPipeEventSource(stream);
Task readerTask = Task.Run(() => source.Process());
await Task.Delay(500);
Logger.logger.Log("Stopping EventPipeSession over standard connection");
EventPipeClient.StopTracing(pid, sessionId);
await readerTask;
Logger.logger.Log("Stopped EventPipeSession over standard connection");
});

Task reverseTask = Task.Run(async () =>
{
var ad1 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
Logger.logger.Log(ad1.ToString());
var ad2 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
Logger.logger.Log(ad2.ToString());
var ad3 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
Logger.logger.Log(ad3.ToString());
var ad4 = await Utils.WaitTillTimeout(ReverseServer.CreateServerAndReceiveAdvertisement(serverName), TimeSpan.FromMilliseconds(_maxPollTimeMS));
Logger.logger.Log(ad4.ToString());
});

await Task.WhenAll(reverseTask, regularTask);
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));

return fSuccess;
}

public static async Task<bool> TEST_StandardConnectionStillWorksIfReverseConnectionIsBroken()
{
bool fSuccess = true;
Expand Down Expand Up @@ -304,7 +245,7 @@ public static async Task<bool> TEST_StandardConnectionStillWorksIfReverseConnect
}
);

fSuccess &= await Utils.WaitTillTimeout(subprocessTask, TimeSpan.FromMinutes(1));
fSuccess &= await subprocessTask;

return fSuccess;
}
Expand All @@ -320,6 +261,8 @@ public static async Task<int> Main(string[] args)
}

bool fSuccess = true;
if (!IpcTraceTest.EnsureCleanEnvironment())
return -1;
IEnumerable<MethodInfo> tests = typeof(ReverseValidation).GetMethods().Where(mi => mi.Name.StartsWith("TEST_"));
foreach (var test in tests)
{
Expand Down
2 changes: 1 addition & 1 deletion src/coreclr/tests/src/tracing/eventpipe/reverse/reverse.csproj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@
<OutputType>exe</OutputType>
<CLRTestKind>BuildAndRun</CLRTestKind>
<AllowUnsafeBlocks>true</AllowUnsafeBlocks>
<CLRTestPriority>0</CLRTestPriority>
<CLRTestPriority>1</CLRTestPriority>
<UnloadabilityIncompatible>true</UnloadabilityIncompatible>
<JitOptimizationSensitive>true</JitOptimizationSensitive>
<!-- Disable for GCStress due to test failure: https://github.com/dotnet/runtime/issues/38524 -->
Expand Down
Loading

0 comments on commit 7c891ca

Please sign in to comment.