diff --git a/src/Microsoft.TestPlatform.PlatformAbstractions/common/System/ProcessHelper.cs b/src/Microsoft.TestPlatform.PlatformAbstractions/common/System/ProcessHelper.cs index 0c84c45261..0740261725 100644 --- a/src/Microsoft.TestPlatform.PlatformAbstractions/common/System/ProcessHelper.cs +++ b/src/Microsoft.TestPlatform.PlatformAbstractions/common/System/ProcessHelper.cs @@ -6,10 +6,9 @@ using System.Diagnostics; using System.Globalization; using System.IO; +using System.Runtime.CompilerServices; using System.Threading; -#if !NET using System.Threading.Tasks; -#endif using Microsoft.VisualStudio.TestPlatform.PlatformAbstractions.Interfaces; @@ -23,6 +22,23 @@ public partial class ProcessHelper : IProcessHelper private static readonly string Arm = "arm"; private readonly Process _currentProcess = Process.GetCurrentProcess(); + // Bounded time (ms) we wait for a crashed process's redirected stderr to reach EOF before reading it, + // so a late-delivered crash callstack (e.g. "Stack overflow.") is not dropped. See the Exited handler. + private const int CrashErrorDrainTimeout = 5000; + + // Bounded time (ms) we wait for stderr to drain after a clean exit, kept short so neither the common + // case nor the rare grandchild-keeps-the-pipe-open case adds latency. See the Exited handler. + private const int CleanExitErrorDrainTimeout = 500; + + // Processes we deliberately killed (e.g. when aborting or cleaning up a run). Their abnormal exit code is + // expected and is not a crash, so the exit handler must not spend the long stderr-drain budget on them - + // that would make aborting a run from an IDE slow whenever a grandchild process (e.g. a browser driver) + // keeps the stderr pipe open. ConditionalWeakTable holds only weak references to the processes, so entries + // disappear when a process is collected and nothing has to be removed explicitly. + private readonly ConditionalWeakTable _deliberatelyTerminatedProcesses = new(); + private readonly object _deliberatelyTerminatedProcessesLock = new(); + private static readonly object DeliberateTerminationMarker = new(); + #if !NET private readonly IEnvironment _environment; #endif @@ -127,20 +143,22 @@ void InitializeAndStart() process.OutputDataReceived += (sender, args) => outputCallBack(sender as Process, args.Data); } - // Set once the redirected stderr stream reaches EOF (signaled by a null Data event, + // Completed once the redirected stderr stream reaches EOF (signaled by a null Data event, // which is raised after all stderr lines have been handed to errorCallback). This is // the only reliable signal that the asynchronously-collected error output is complete: // neither WaitForExit(timeout) nor WaitForExitAsync guarantees the ErrorDataReceived - // callbacks have run. The exit handler below waits (bounded) on this before reading. - ManualResetEventSlim? errorStreamClosed = null; + // callbacks have run. The exit handler below awaits (bounded) on this before reading. + TaskCompletionSource? errorStreamClosed = null; if (errorCallback != null) { - errorStreamClosed = new ManualResetEventSlim(initialState: false); + // RunContinuationsAsynchronously so completing this from the ErrorDataReceived callback does not + // inline the exit handler's continuation onto the stderr-reader thread. + errorStreamClosed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); process.ErrorDataReceived += (sender, args) => { if (args.Data is null) { - errorStreamClosed.Set(); + errorStreamClosed.TrySetResult(true); } errorCallback(sender as Process, args.Data); @@ -151,8 +169,8 @@ void InitializeAndStart() { process.Exited += async (sender, args) => { - const int timeout = 500; - var stopwatch = Stopwatch.StartNew(); + // Bounded time we give the process to fully exit after we are notified of its exit. + const int processExitTimeout = 500; if (sender is Process p) { @@ -172,7 +190,9 @@ void InitializeAndStart() // // For older frameworks, the solution is more tricky but it seems we can get the expected // behavior using the parameterless 'WaitForExit()' combined with an awaited Task.Run call. - var cts = new CancellationTokenSource(timeout); + // 'using' so the timer the timeout allocates is released as soon as we are done waiting, + // instead of leaking one per process exit when many test hosts are spawned. + using var cts = new CancellationTokenSource(processExitTimeout); #if NET await p.WaitForExitAsync(cts.Token); #else @@ -191,7 +211,7 @@ void InitializeAndStart() // the testhost to become a zombie process in the first place. if (_environment.OperatingSystem is PlatformOperatingSystem.Windows) { - p.WaitForExit(timeout); + p.WaitForExit(processExitTimeout); } else { @@ -201,7 +221,11 @@ void InitializeAndStart() { if (!p.HasExited) { - p.Kill(); + // We are force-killing a process that overran the exit budget (e.g. a + // grandchild keeps it hanging). Coordinate the kill with the marker so + // the exit handler uses the short abort budget only when our kill wins + // a race with the process exiting naturally. + KillProcess(p); } } catch @@ -222,12 +246,28 @@ void InitializeAndStart() // the exit) or InvalidOperationException. } - // The process has exited. Within the SAME bounded budget used above, wait for the - // redirected stderr to reach EOF so that asynchronously-collected error output - // (e.g. a testhost crash callstack such as "Stack overflow.") is complete before the - // exit callback consumes it. WaitForExit(timeout)/WaitForExitAsync do not guarantee - // the ErrorDataReceived callbacks have run. - WaitForErrorStreamToDrain(errorStreamClosed, timeout, stopwatch.ElapsedMilliseconds); + // The process has exited. Asynchronously wait (bounded) for the redirected stderr to reach + // EOF so that asynchronously-collected error output (e.g. a testhost crash callstack such as + // "Stack overflow.") is complete before the exit callback consumes it. + // WaitForExit(timeout)/WaitForExitAsync do not guarantee the ErrorDataReceived callbacks + // have run. + // + // We await rather than block here on purpose: the crash callstack can be delivered to + // ErrorDataReceived noticeably late under load (e.g. thread-pool starvation while many test + // hosts run in parallel on CI), and blocking a thread-pool thread for the whole drain budget + // would compete with the very ErrorDataReceived callback we are waiting for and could starve + // it out. Dropping that output both produces a misleading error message and makes + // RunTestsShouldThrowOnStackOverflowException flaky. + // + // This drain budget is intentionally separate from (and far more generous than) the + // process-exit budget above, and the generous part is only spent when the process crashed - + // i.e. it exited abnormally on its own. A clean exit, or a process we deliberately killed + // (e.g. aborting a run from an IDE), gets only a short grace period so we never add latency + // to those cases - in particular we must not hang for seconds on abort when a grandchild + // process keeps the stderr pipe open and EOF never arrives. In every case the wait returns + // as soon as EOF is observed, so a process that exits and drains promptly pays almost nothing. + var errorDrainTimeout = GetErrorDrainTimeout(DidProcessExitCleanly(p), WasDeliberatelyTerminated(p)); + await WaitForErrorStreamToDrainAsync(errorStreamClosed, errorDrainTimeout).ConfigureAwait(false); } // If exit callback has code that access Process object, ensure that the exceptions handling should be done properly. @@ -252,24 +292,87 @@ void InitializeAndStart() } /// - /// Waits, bounded by the time remaining in , for the redirected - /// standard error stream to reach EOF (signaled via ). This ensures - /// all callbacks have completed - and therefore the captured - /// error output is complete - before it is consumed by the exit callback. It returns immediately when - /// there is no redirected error stream, when it has already drained, or when the budget is already - /// exhausted (e.g. a grandchild process keeps the pipe open), so the caller can never hang. + /// Asynchronously waits, bounded by , for the redirected standard + /// error stream to reach EOF (signaled by completing ). This ensures all + /// callbacks have completed - and therefore the captured error + /// output is complete - before it is consumed by the exit callback. It returns immediately when there is + /// no redirected error stream, when the timeout is not positive, or when the stream has already drained + /// (the common case), and is otherwise bounded by the timeout (e.g. a grandchild process keeps the pipe + /// open), so the caller can never hang. It deliberately does not + /// block the calling thread while waiting, so it does not consume a thread-pool thread that the pending + /// callback may itself need in order to deliver EOF under + /// thread-pool starvation. /// - internal static void WaitForErrorStreamToDrain(ManualResetEventSlim? errorStreamClosed, int budgetMilliseconds, long elapsedMilliseconds) + internal static async Task WaitForErrorStreamToDrainAsync(TaskCompletionSource? errorStreamClosed, int timeoutMilliseconds) { - if (errorStreamClosed is null) + if (errorStreamClosed is null || timeoutMilliseconds <= 0 || errorStreamClosed.Task.IsCompleted) { return; } - var remainingMilliseconds = budgetMilliseconds - (int)elapsedMilliseconds; - if (remainingMilliseconds > 0) + using var timeoutCancellation = new CancellationTokenSource(); + var delayTask = Task.Delay(timeoutMilliseconds, timeoutCancellation.Token); + var completedTask = await Task.WhenAny(errorStreamClosed.Task, delayTask).ConfigureAwait(false); + + // Stop the timer as soon as the stream drains so we don't leave it pending for the whole timeout. + if (completedTask != delayTask) + { + timeoutCancellation.Cancel(); + } + } + + /// + /// Returns when the process has exited with a zero exit code. A non-zero exit code + /// (a crash) - or an exit code that cannot be retrieved - is treated as not-clean so the caller waits the + /// longer stderr drain budget and does not truncate potentially important crash output. + /// + private static bool DidProcessExitCleanly(Process process) + { + try + { + return process.HasExited && process.ExitCode == 0; + } + catch + { + // If the exit code is not retrievable (e.g. the process handle is gone), assume a crash so we + // give the redirected stderr the longer budget to drain. + return false; + } + } + + /// + /// Picks the bounded time we are willing to wait for the redirected stderr to reach EOF. A genuine crash + /// (an abnormal exit we did not cause) gets the generous budget so a late-delivered crash callstack is + /// captured; a clean exit, or a process we deliberately killed (an abort/cleanup), gets only the short + /// budget so we never add latency to those cases. + /// + internal static int GetErrorDrainTimeout(bool exitedCleanly, bool deliberatelyTerminated) + => exitedCleanly || deliberatelyTerminated ? CleanExitErrorDrainTimeout : CrashErrorDrainTimeout; + + private void KillProcess(Process process) + => KillProcess(process, static process => process.Kill()); + + internal void KillProcess(Process process, Action killProcess) + { + lock (_deliberatelyTerminatedProcessesLock) + { + // Kill can race with a natural process exit. Keep the exit handler from reading the marker until + // Kill reports its outcome, and publish the marker only after a successful kill. If Kill throws + // because the process exited first, the exit remains unmarked and receives the crash drain budget. + killProcess(process); + + if (!_deliberatelyTerminatedProcesses.TryGetValue(process, out _)) + { + _deliberatelyTerminatedProcesses.Add(process, DeliberateTerminationMarker); + } + } + } + + internal bool WasDeliberatelyTerminated(Process process) + { + lock (_deliberatelyTerminatedProcessesLock) { - errorStreamClosed.Wait(remainingMilliseconds); + return _deliberatelyTerminatedProcesses.TryGetValue(process, out _); } } @@ -346,7 +449,9 @@ public void TerminateProcess(object? process) { if (process is Process proc && !proc.HasExited) { - proc.Kill(); + // Coordinate the kill with its marker so a process that exits naturally between HasExited and + // Kill is not misclassified as a deliberate termination. + KillProcess(proc); } } catch (InvalidOperationException) diff --git a/test/vstest.console.UnitTests/ProcessHelperTests.cs b/test/vstest.console.UnitTests/ProcessHelperTests.cs index d9a00cff82..e3a78d3c35 100644 --- a/test/vstest.console.UnitTests/ProcessHelperTests.cs +++ b/test/vstest.console.UnitTests/ProcessHelperTests.cs @@ -1,8 +1,9 @@ // Copyright (c) Microsoft Corporation. All rights reserved. // Licensed under the MIT license. See LICENSE file in the project root for full license information. +using System; using System.Diagnostics; -using System.Threading; +using System.Threading.Tasks; using Microsoft.VisualStudio.TestPlatform.PlatformAbstractions; @@ -11,7 +12,7 @@ namespace Microsoft.VisualStudio.TestPlatform.CommandLine.UnitTests; /// -/// Tests for , the bounded wait that lets the process +/// Tests for , the bounded wait that lets the process /// exit callback observe the complete standard error output of a crashed test host. Without it, the exit /// callback could read the asynchronously-collected stderr before all ErrorDataReceived callbacks had run, /// dropping a crash callstack such as "Stack overflow." (the cause of the flaky @@ -23,46 +24,66 @@ public class ProcessHelperTests private const int BudgetMs = 500; [TestMethod] - public void WaitForErrorStreamToDrainShouldReturnOnceTheErrorStreamCloses() + public async Task WaitForErrorStreamToDrainShouldReturnOnceTheErrorStreamCloses() { - using var errorStreamClosed = new ManualResetEventSlim(initialState: false); + // EOF arrives AFTER we start waiting, mimicking a slow ErrorDataReceived delivery that lands just after + // the exit handler begins draining. Start the wait first and assert it is still in progress, then signal + // EOF: the wait must observe that late completion and return promptly - not return early (dropping the + // crash callstack) and not block to the timeout. + var errorStreamClosed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + + var drainTask = ProcessHelper.WaitForErrorStreamToDrainAsync(errorStreamClosed, timeoutMilliseconds: 5000); + Assert.IsFalse(drainTask.IsCompleted, "The wait must still be in progress before the error stream drains."); + + // The late ErrorDataReceived EOF finally arrives; the wait must observe it and return promptly. The + // budget above is far larger than this should take, so if the wait ignored EOF and always ran to the + // timeout the elapsed-time assertion below would catch it (the await would take ~5s, not a few ms). + var stopwatch = Stopwatch.StartNew(); + errorStreamClosed.TrySetResult(true); + + await drainTask; + stopwatch.Stop(); + + Assert.IsTrue(errorStreamClosed.Task.IsCompleted, "The method must wait until the error stream is drained."); + Assert.IsLessThan( + 2000L, + stopwatch.ElapsedMilliseconds, + $"The wait must return as soon as the late EOF is observed, not run to the timeout (took {stopwatch.ElapsedMilliseconds} ms)."); + } - // The stream reaches EOF a little later, mimicking a slow ErrorDataReceived delivery. - var setter = new Thread(() => - { - Thread.Sleep(150); - errorStreamClosed.Set(); - }) - { IsBackground = true }; + [TestMethod] + public async Task WaitForErrorStreamToDrainShouldReturnImmediatelyWhenAlreadyDrained() + { + // The stream has already reached EOF (all ErrorDataReceived callbacks have been delivered) before we + // start waiting, so the common fast path must not add any latency. + var errorStreamClosed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + errorStreamClosed.TrySetResult(true); var stopwatch = Stopwatch.StartNew(); - setter.Start(); - ProcessHelper.WaitForErrorStreamToDrain(errorStreamClosed, budgetMilliseconds: 5000, elapsedMilliseconds: 0); + await ProcessHelper.WaitForErrorStreamToDrainAsync(errorStreamClosed, timeoutMilliseconds: 5000); stopwatch.Stop(); - setter.Join(); - Assert.IsTrue(errorStreamClosed.IsSet, "The method must wait until the error stream is drained."); Assert.IsLessThan( - 3000L, + 250L, stopwatch.ElapsedMilliseconds, - $"The method should return shortly after the stream closes, not at the budget timeout (took {stopwatch.ElapsedMilliseconds} ms)."); + $"When the stream is already drained the method must return immediately (took {stopwatch.ElapsedMilliseconds} ms)."); } [TestMethod] - public void WaitForErrorStreamToDrainShouldBeBoundedWhenTheErrorStreamNeverCloses() + public async Task WaitForErrorStreamToDrainShouldBeBoundedWhenTheErrorStreamNeverCloses() { // Models a grandchild process keeping the pipe open: EOF never arrives. - using var errorStreamClosed = new ManualResetEventSlim(initialState: false); + var errorStreamClosed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var stopwatch = Stopwatch.StartNew(); - ProcessHelper.WaitForErrorStreamToDrain(errorStreamClosed, BudgetMs, elapsedMilliseconds: 0); + await ProcessHelper.WaitForErrorStreamToDrainAsync(errorStreamClosed, BudgetMs); stopwatch.Stop(); - Assert.IsFalse(errorStreamClosed.IsSet, "Precondition: the stream never closes in this test."); + Assert.IsFalse(errorStreamClosed.Task.IsCompleted, "Precondition: the stream never closes in this test."); Assert.IsGreaterThanOrEqualTo( 150L, stopwatch.ElapsedMilliseconds, - $"The method should wait roughly the budget for the stream (waited only {stopwatch.ElapsedMilliseconds} ms)."); + $"The method should wait roughly the timeout for the stream (waited only {stopwatch.ElapsedMilliseconds} ms)."); Assert.IsLessThan( 5000L, stopwatch.ElapsedMilliseconds, @@ -70,28 +91,28 @@ public void WaitForErrorStreamToDrainShouldBeBoundedWhenTheErrorStreamNeverClose } [TestMethod] - public void WaitForErrorStreamToDrainShouldNotWaitWhenTheBudgetIsAlreadyExhausted() + public async Task WaitForErrorStreamToDrainShouldNotWaitWhenTimeoutIsNotPositive() { - // The exit wait above already consumed the whole budget (e.g. a slow grandchild), so there is no - // time left to wait for stderr - we must not add any latency on top. - using var errorStreamClosed = new ManualResetEventSlim(initialState: false); + // A non-positive timeout means there is no time budget left to wait for stderr - we must not add + // any latency on top. + var errorStreamClosed = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var stopwatch = Stopwatch.StartNew(); - ProcessHelper.WaitForErrorStreamToDrain(errorStreamClosed, BudgetMs, elapsedMilliseconds: BudgetMs + 100); + await ProcessHelper.WaitForErrorStreamToDrainAsync(errorStreamClosed, timeoutMilliseconds: 0); stopwatch.Stop(); - Assert.IsFalse(errorStreamClosed.IsSet); + Assert.IsFalse(errorStreamClosed.Task.IsCompleted); Assert.IsLessThan( 250L, stopwatch.ElapsedMilliseconds, - $"With the budget exhausted the method must return immediately (took {stopwatch.ElapsedMilliseconds} ms)."); + $"With a non-positive timeout the method must return immediately (took {stopwatch.ElapsedMilliseconds} ms)."); } [TestMethod] - public void WaitForErrorStreamToDrainShouldReturnImmediatelyWhenThereIsNoErrorStream() + public async Task WaitForErrorStreamToDrainShouldReturnImmediatelyWhenThereIsNoErrorStream() { var stopwatch = Stopwatch.StartNew(); - ProcessHelper.WaitForErrorStreamToDrain(errorStreamClosed: null, BudgetMs, elapsedMilliseconds: 0); + await ProcessHelper.WaitForErrorStreamToDrainAsync(errorStreamClosed: null, BudgetMs); stopwatch.Stop(); Assert.IsLessThan( @@ -99,4 +120,40 @@ public void WaitForErrorStreamToDrainShouldReturnImmediatelyWhenThereIsNoErrorSt stopwatch.ElapsedMilliseconds, $"With no redirected error stream the method must be a no-op (took {stopwatch.ElapsedMilliseconds} ms)."); } + + [TestMethod] + public void GetErrorDrainTimeoutShouldUseTheGenerousBudgetOnlyForACrash() + { + // A crash is an abnormal exit we did not cause: not a clean exit and not something we killed. + var crash = ProcessHelper.GetErrorDrainTimeout(exitedCleanly: false, deliberatelyTerminated: false); + var cleanExit = ProcessHelper.GetErrorDrainTimeout(exitedCleanly: true, deliberatelyTerminated: false); + var aborted = ProcessHelper.GetErrorDrainTimeout(exitedCleanly: false, deliberatelyTerminated: true); + var cleanAndAborted = ProcessHelper.GetErrorDrainTimeout(exitedCleanly: true, deliberatelyTerminated: true); + + Assert.IsGreaterThan( + cleanExit, + crash, + "A crash must wait longer for stderr to drain than a clean exit, so a late crash callstack is captured."); + + // A process we deliberately killed (e.g. aborting from an IDE) must drain as fast as a clean exit, so + // an abort never hangs for seconds when a grandchild keeps the stderr pipe open. + Assert.AreEqual(cleanExit, aborted, "A deliberately terminated process must use the short (clean-exit) budget."); + Assert.AreEqual(cleanExit, cleanAndAborted, "A clean, deliberately terminated process must use the short budget."); + } + + [TestMethod] + public void KillProcessShouldNotMarkNaturalExitWhenKillLosesRace() + { + using var process = Process.GetCurrentProcess(); + var processHelper = new ProcessHelper(); + + Assert.ThrowsExactly( + () => processHelper.KillProcess( + process, + _ => throw new InvalidOperationException("The process exited naturally before Kill."))); + + Assert.IsFalse( + processHelper.WasDeliberatelyTerminated(process), + "A natural exit that wins the race with Kill must retain the generous crash drain budget."); + } }