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 dfea41b33e9c7874c1069349a539207020f23bcd..b8b604be164946fb17704c79f134e7a25605afb5 100644 (file)
--- 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 d1526e32bbaa0247579c2e46ebf25bf0dcb934cb..b85d1379adb6c4bd5f8ea22bd5c26c7cf15a51db 100644 (file)
--- 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 d51da6c99ac774984c17cd34ab98228a5f61306f..3eed11736a01be47d312eab6c7df8246bdcec81c 100644 (file)
--- 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<ObjectDisposedException>(() => 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<OperationCanceledException>(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<ObjectDisposedException>(() => 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 0c6ebbebd096e406a063736af94658ee76cbb896..2f883bceb2595df2d339dfac239f2a4b9ed95534 100644 (file)
--- 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 c01d946c920acf3ac18a2bd145fe6c9e79d7df8c..22e74e9673efc27b05d67d7fbcea9fa9e55e1d18 100644 (file)
--- 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 e37a0f87c913cf16492a65116ab7e7503632c8fc..4b37afe6277136ca2775af28176e87c887adc10a 100644 (file)
--- 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
             {