From: Wiktor Kopec Date: Tue, 27 Apr 2021 19:12:53 +0000 (-0700) Subject: Fix hang when cancelling reading from trace calls (#2203) X-Git-Tag: submit/tizen/20210909.063632~15^2~74 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=cbdc8e4936225fb094618d68601ac38668afa76f;p=platform%2Fcore%2Fdotnet%2Fdiagnostics.git Fix hang when cancelling reading from trace calls (#2203) --- diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Trace/EventTracePipeline.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Trace/EventTracePipeline.cs index dfea41b33..b8b604be1 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Trace/EventTracePipeline.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Trace/EventTracePipeline.cs @@ -30,7 +30,9 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe { try { - Stream eventStream = await _provider.Value.ProcessEvents(Client, Settings.Duration, token); + //It is important that the underlying stream be completely read, or disposed. + //If rundown is enabled, the underlying stream must be drained or disposed, or the app hangs. + using Stream eventStream = await _provider.Value.ProcessEvents(Client, Settings.Duration, token); await _onStreamAvailable(eventStream, token); } diff --git a/src/tests/EventPipeTracee/Program.cs b/src/tests/EventPipeTracee/Program.cs index d1526e32b..b85d1379a 100644 --- a/src/tests/EventPipeTracee/Program.cs +++ b/src/tests/EventPipeTracee/Program.cs @@ -16,6 +16,7 @@ namespace EventPipeTracee private static void TestBody(string loggerCategory) { Console.Error.WriteLine("Starting remote test process"); + Console.Error.Flush(); ServiceCollection serviceCollection = new ServiceCollection(); serviceCollection.AddLogging(builder => @@ -27,26 +28,26 @@ namespace EventPipeTracee var logger = loggerFactory.CreateLogger(loggerCategory); Console.Error.WriteLine($"{DateTime.UtcNow} Awaiting start"); + Console.Error.Flush(); if (Console.Read() == -1) { throw new InvalidOperationException("Unable to receive start signal"); } Console.Error.WriteLine($"{DateTime.UtcNow} Starting test body"); + Console.Error.Flush(); TestBodyCore(logger); //Signal end of test data Console.WriteLine("1"); Console.Error.WriteLine($"{DateTime.UtcNow} Awaiting end"); + Console.Error.Flush(); if (Console.Read() == -1) { throw new InvalidOperationException("Unable to receive end signal"); } - - - Console.Error.WriteLine($"{DateTime.UtcNow} Ending remote test process"); } diff --git a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventTracePipelineUnitTests.cs b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventTracePipelineUnitTests.cs index d51da6c99..3eed11736 100644 --- a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventTracePipelineUnitTests.cs +++ b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/EventTracePipelineUnitTests.cs @@ -33,7 +33,7 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests public async Task TestTraceStopAsync() { using var buffer = new MemoryStream(); - + Stream eventStream = null; await using (var testExecution = StartTraceeProcess("TraceStopTest")) { //TestRunner should account for start delay to make sure that the diagnostic pipe is available. @@ -47,13 +47,16 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests await using var pipeline = new EventTracePipeline(client, settings, async (s, token) => { - //The buffer must be read in order to not hang. The Stop message will not be processed otherwise. await s.CopyToAsync(buffer); + eventStream = s; }); await PipelineTestUtilities.ExecutePipelineWithDebugee(pipeline, testExecution); } + //Validate that the stream is only valid for the lifetime of the callback in the trace pipeline. + Assert.Throws(() => eventStream.Read(new byte[4], 0, 4)); + Assert.True(buffer.Length > 0); var eventSource = new EventPipeEventSource(buffer); @@ -70,6 +73,42 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests Assert.True(foundCpuProvider); } + [SkippableFact] + public async Task TestEventStreamCleanup() + { + if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + throw new SkipTestException("Test debugee sigfaults for OSX/Linux"); + } + + Stream eventStream = null; + using var cancellationTokenSource = new CancellationTokenSource(); + await using (var testExecution = StartTraceeProcess("TestEventStreamCleanup")) + { + //TestRunner should account for start delay to make sure that the diagnostic pipe is available. + + var client = new DiagnosticsClient(testExecution.TestRunner.Pid); + var settings = new EventTracePipelineSettings() + { + Duration = Timeout.InfiniteTimeSpan, + Configuration = new CpuProfileConfiguration() + }; + + await using var pipeline = new EventTracePipeline(client, settings, (s, token) => + { + eventStream = s; //Clients should not do this. + cancellationTokenSource.Cancel(); + token.ThrowIfCancellationRequested(); + return Task.CompletedTask; + }); + + await Assert.ThrowsAsync(async () => await PipelineTestUtilities.ExecutePipelineWithDebugee(pipeline, testExecution, cancellationTokenSource.Token)); + } + + //Validate that the stream is only valid for the lifetime of the callback in the trace pipeline. + Assert.Throws(() => eventStream.Read(new byte[4], 0, 4)); + } + private RemoteTestExecution StartTraceeProcess(string loggerCategory) { return RemoteTestExecution.StartProcess(CommonHelper.GetTraceePathWithArgs("EventPipeTracee") + " " + loggerCategory, _output); diff --git a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/PipelineTestUtilities.cs b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/PipelineTestUtilities.cs index 0c6ebbebd..2f883bceb 100644 --- a/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/PipelineTestUtilities.cs +++ b/src/tests/Microsoft.Diagnostics.Monitoring.EventPipe/PipelineTestUtilities.cs @@ -10,9 +10,9 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests { internal static class PipelineTestUtilities { - public static async Task ExecutePipelineWithDebugee(Pipeline pipeline, RemoteTestExecution testExecution) + public static async Task ExecutePipelineWithDebugee(Pipeline pipeline, RemoteTestExecution testExecution, CancellationToken token = default) { - Task processingTask = pipeline.RunAsync(CancellationToken.None); + Task processingTask = pipeline.RunAsync(token); //Begin event production testExecution.SendSignal(); @@ -20,15 +20,19 @@ namespace Microsoft.Diagnostics.Monitoring.EventPipe.UnitTests //Wait for event production to be done testExecution.WaitForSignal(); - //Signal for the pipeline to stop - await pipeline.StopAsync(); - - //After a pipeline is stopped, we should expect the RunTask to eventually finish - await processingTask; - - //Signal for debugee that's ok to end/move on. - testExecution.SendSignal(); + try + { + //Signal for the pipeline to stop + await pipeline.StopAsync(token); + //After a pipeline is stopped, we should expect the RunTask to eventually finish + await processingTask; + } + finally + { + //Signal for debugee that's ok to end/move on. + testExecution.SendSignal(); + } } } } diff --git a/src/tests/Microsoft.Diagnostics.NETCore.Client/RemoteTestExecution.cs b/src/tests/Microsoft.Diagnostics.NETCore.Client/RemoteTestExecution.cs index c01d946c9..22e74e967 100644 --- a/src/tests/Microsoft.Diagnostics.NETCore.Client/RemoteTestExecution.cs +++ b/src/tests/Microsoft.Diagnostics.NETCore.Client/RemoteTestExecution.cs @@ -81,8 +81,7 @@ namespace Microsoft.Diagnostics.NETCore.Client.UnitTests } catch (Exception e) { - outputHelper.WriteLine(e.ToString()); - throw; + outputHelper.WriteLine("Error reading standard error from child process: " + e.ToString()); } } catch (ObjectDisposedException) diff --git a/src/tests/Microsoft.Diagnostics.NETCore.Client/TestRunner.cs b/src/tests/Microsoft.Diagnostics.NETCore.Client/TestRunner.cs index e37a0f87c..4b37afe62 100644 --- a/src/tests/Microsoft.Diagnostics.NETCore.Client/TestRunner.cs +++ b/src/tests/Microsoft.Diagnostics.NETCore.Client/TestRunner.cs @@ -143,7 +143,7 @@ namespace Microsoft.Diagnostics.NETCore.Client { if (testProcess.HasExited) { - outputHelper.WriteLine($"Process {testProcess.Id} status: Exited"); + outputHelper.WriteLine($"Process {testProcess.Id} status: Exited {testProcess.ExitCode}"); } else {