From 08ed77db9f48c49c7f079e213291ebf7af6a0bb7 Mon Sep 17 00:00:00 2001 From: Alexandre Zollinger Chohfi Date: Thu, 13 Aug 2026 17:11:33 -0700 Subject: [PATCH] Fix the two flaky tests taking down build-and-package Ten consecutive Build and Package failures came from two independent flaky tests, not one. RunDotnetProcessAsync_Cancellation_KillsProcessTree timed out waiting for its PID file. Start-Process failure is a NON-terminating error, so the root script carried on to Set-Content with $p still null, published a 0-byte file, and left the reader polling something that would never parse -- then reported the file "was not written" about a file that had in fact been written, empty. The child's stderr was redirected and discarded, so the real reason never reached CI. #732 fixed a different failure mode in this helper (a sharing violation); this timeout signature predates that fix and still reproduces on commits containing it. AnalyzeDumpAsync_RealManagedDump_RunsClrMdManagedEnumeration dumped a PowerShell child after a blind 1.5s sleep. Under load the child was still in native startup -- CI dumps show only hostfxr/hostpolicy loading coreclr -- so ClrMD found no runtime and the "CLR Version" assertion failed. Nothing had ever fixed this one. Fixes: - $ErrorActionPreference = 'Stop' plus an explicit null guard, so a failed child start aborts before Set-Content instead of publishing an empty file - WaitForPidFileAsync watches the launcher task and fails fast with the root's exit code and stderr rather than waiting out the clock - the timeout message now distinguishes never-created, unreadable, and created-but-unparsable - the managed child allocates, collects, and only then signals readiness, so the dump is taken with the runtime up AND its heap walkable Signalling readiness alone was not enough: a token emitted from the first line of managed code made the dump test fail or go inconclusive on a machine where the old sleep passed 6/6, which is why the child warms its heap before signalling. The script builder is shared with its regression test so the script proven not to publish an empty file is the one the tree-kill test runs. Verified by removing the fix: the guard fails with the original script and passes with the hardened one. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: c8e8ead7-3a65-4148-b196-a4c217fde912 --- .../WinApp.Cli.Tests/DotNetServiceTests.cs | 179 ++++++++++++++++-- .../WinApp.Cli.Tests/TestProcessDump.cs | 74 +++++--- 2 files changed, 216 insertions(+), 37 deletions(-) diff --git a/src/winapp-CLI/WinApp.Cli.Tests/DotNetServiceTests.cs b/src/winapp-CLI/WinApp.Cli.Tests/DotNetServiceTests.cs index 664a28733..59e584f79 100644 --- a/src/winapp-CLI/WinApp.Cli.Tests/DotNetServiceTests.cs +++ b/src/winapp-CLI/WinApp.Cli.Tests/DotNetServiceTests.cs @@ -1704,13 +1704,7 @@ public async Task RunDotnetProcessAsync_Cancellation_KillsProcessTree() // with -PassThru, writes ping's PID to a temp file, then blocks on Wait-Process. The test polls // that file — no WMI or Win32 process enumeration required. var pidFile = Path.Join(Path.GetTempPath(), $"winapp_treekill_{Guid.NewGuid():N}.pid"); - // Escape single quotes for the single-quoted PowerShell string literal so a temp path - // containing an apostrophe (e.g. a profile like O'Brien) still produces a valid script. - var pidFileLiteral = pidFile.Replace("'", "''"); - var script = - "$p = Start-Process -FilePath ping.exe -ArgumentList '-n','60','127.0.0.1' -PassThru -WindowStyle Hidden; " + - $"Set-Content -LiteralPath '{pidFileLiteral}' -Value $p.Id; " + - "Wait-Process -Id $p.Id"; + var script = BuildTreeKillScript(pidFile, "ping.exe"); var startInfo = new ProcessStartInfo { @@ -1744,8 +1738,11 @@ public async Task RunDotnetProcessAsync_Cancellation_KillsProcessTree() rootPid = rootPidValue; Assert.IsFalse(Process.GetProcessById(rootPidValue).HasExited, "The root process should be running before cancellation."); - // Capture the ping descendant via the PID file the root script writes. - var pingPidValue = await WaitForPidFileAsync(pidFile, TimeSpan.FromSeconds(15), TestContext.CancellationToken); + // Capture the ping descendant via the PID file the root script writes. The run task is passed + // in so a root that dies before publishing fails here with its own stderr rather than after a + // silent wait. The budget is generous because it costs nothing on success (a healthy spawn + // publishes in well under a second) and only bounds a genuinely wedged agent. + var pingPidValue = await WaitForPidFileAsync(pidFile, TimeSpan.FromSeconds(30), TestContext.CancellationToken, runTask); pingPid = pingPidValue; Assert.IsFalse(Process.GetProcessById(pingPidValue).HasExited, "The ping descendant should be running before cancellation."); @@ -1795,6 +1792,38 @@ public async Task RunDotnetProcessAsync_Cancellation_KillsProcessTree() } } + /// + /// Builds the root script for the tree-kill test: start , publish its PID + /// to , then block until it exits. + /// + /// + /// $ErrorActionPreference = 'Stop' is what keeps the published PID file honest, and it is the + /// fix for a CI flake rather than boilerplate. A Start-Process failure is a NON-terminating + /// error by default, so the script used to carry straight on to Set-Content with $p + /// still null, publish a 0-byte file, and leave the reader polling a file that would never parse + /// until its whole budget expired — reporting that the file "was not written" about a file that had + /// in fact been written, just empty. Stopping on the error means the root exits instead, with the + /// real reason on stderr for to surface. + /// + /// Shared with the regression test so the script proven not to publish an empty file is the very + /// script the tree-kill test runs, and the two cannot drift apart. + /// + /// + private static string BuildTreeKillScript(string pidFile, string childExe) + { + // Escape single quotes for the single-quoted PowerShell string literals so a temp path + // containing an apostrophe (e.g. a profile like O'Brien) still produces a valid script. + var pidFileLiteral = pidFile.Replace("'", "''"); + var childExeLiteral = childExe.Replace("'", "''"); + + return + "$ErrorActionPreference = 'Stop'; " + + $"$p = Start-Process -FilePath '{childExeLiteral}' -ArgumentList '-n','60','127.0.0.1' -PassThru -WindowStyle Hidden; " + + "if ($null -eq $p) { throw 'Start-Process returned no process object' }; " + + $"Set-Content -LiteralPath '{pidFileLiteral}' -Value $p.Id; " + + "Wait-Process -Id $p.Id"; + } + /// Best-effort force-kill of a process (and its tree) by id, ignoring already-exited processes. private static void KillProcessTreeIfRunning(int? pid) { @@ -1875,10 +1904,23 @@ private static async Task WaitForProcessExitAsync(int pid, CancellationTok /// /// An empty or partially written file is covered by the existing /// guard, which simply keeps polling until the value parses. + /// + /// is the optional launcher task for the process that publishes the file. + /// The PID can only ever arrive from that process, so once it has exited the wait is already lost and + /// running out the clock just delays the failure and throws away the reason. Awaiting the completed + /// task yields its exit code and captured stderr, turning a blind "not written" timeout into the + /// actual error the script reported. + /// /// - private static async Task WaitForPidFileAsync(string pidFile, TimeSpan timeout, CancellationToken cancellationToken) + private static async Task WaitForPidFileAsync( + string pidFile, + TimeSpan timeout, + CancellationToken cancellationToken, + Task<(int ExitCode, string Output, string Error)>? rootTask = null) { var deadline = DateTime.UtcNow + timeout; + var everExisted = false; + string? lastRead = null; while (DateTime.UtcNow < deadline) { string? text = null; @@ -1886,6 +1928,7 @@ private static async Task WaitForPidFileAsync(string pidFile, TimeSpan time { if (File.Exists(pidFile)) { + everExisted = true; text = (await File.ReadAllTextAsync(pidFile, cancellationToken)).Trim(); } } @@ -1894,17 +1937,41 @@ private static async Task WaitForPidFileAsync(string pidFile, TimeSpan time // Still being written (or replaced) by the root script — fall through and retry. } - if (text is not null && int.TryParse(text, out var pid)) + if (text is not null) { - return pid; + lastRead = text; + if (int.TryParse(text, out var pid)) + { + return pid; + } + } + + if (rootTask is { IsCompleted: true }) + { + // Awaiting a faulted task rethrows the original exception, which is at least as + // informative as anything this method could compose. + var (exitCode, output, error) = await rootTask; + throw new InvalidOperationException( + $"The root process exited with code {exitCode} before publishing a descendant PID to " + + $"'{pidFile}'. stderr: {DescribeStream(error)} | stdout: {DescribeStream(output)}"); } await Task.Delay(20, cancellationToken); } - throw new TimeoutException($"The descendant PID file '{pidFile}' was not written within {timeout}."); + var state = (everExisted, lastRead) switch + { + (false, _) => "it was never created", + (true, null) => "it was created but could never be read (the writer held it exclusively for the whole wait)", + _ => $"it was created but never contained a parsable PID (last read: '{lastRead}')", + }; + throw new TimeoutException($"The descendant PID file '{pidFile}' was not usable within {timeout}: {state}."); } + /// Renders a captured stdio stream for a failure message, collapsing it onto one line. + private static string DescribeStream(string? stream) + => string.IsNullOrWhiteSpace(stream) ? "(empty)" : stream.Trim().ReplaceLineEndings(" "); + #endregion #region PID file read (flake regression) @@ -1981,6 +2048,92 @@ await Assert.ThrowsAsync( Assert.IsTrue(File.Exists(pidFile), "The file existed throughout; the timeout came from the parse guard, not a missing file."); } + [TestMethod] + public async Task WaitForPidFile_RootExitedWithoutPublishing_FailsFastWithTheRootsError() + { + // The PID can only ever come from the root process, so once it has exited the wait is already + // lost. The old helper had no idea the root was gone and kept polling to the end of its budget, + // then reported "was not written" -- true, but silent about why. This is the diagnosis half of + // the CI flake fix: the failure must name the root's exit code and stderr. + var pidFile = Path.Join(_tempDirectory.FullName, $"rootdied_{Guid.NewGuid():N}.pid"); + var rootTask = Task.FromResult((ExitCode: 1, Output: "some stdout", Error: "Start-Process : cannot find the file")); + + var sw = Stopwatch.StartNew(); + var ex = await Assert.ThrowsAsync( + async () => await WaitForPidFileAsync(pidFile, TimeSpan.FromSeconds(30), TestContext.CancellationToken, rootTask)); + sw.Stop(); + + StringAssert.Contains(ex.Message, "exited with code 1"); + StringAssert.Contains(ex.Message, "cannot find the file", "The root's stderr is the whole point of the diagnostic."); + Assert.IsLessThan(TimeSpan.FromSeconds(5), sw.Elapsed, + "A dead root must fail fast rather than wait out the full timeout."); + } + + [TestMethod] + public async Task WaitForPidFile_NeverWritten_TimeoutSaysSo() + { + // The timeout message has to distinguish "never created" from "created but unusable", because + // the two point at completely different causes and the old wording ("was not written") was + // actively misleading for the second one. + var pidFile = Path.Join(_tempDirectory.FullName, $"missing_{Guid.NewGuid():N}.pid"); + + var ex = await Assert.ThrowsAsync( + async () => await WaitForPidFileAsync(pidFile, TimeSpan.FromMilliseconds(200), TestContext.CancellationToken)); + + StringAssert.Contains(ex.Message, "never created"); + } + + [TestMethod] + public async Task WaitForPidFile_EmptyFile_TimeoutReportsItWasCreatedButUnparsable() + { + // The exact shape of the CI flake: Set-Content published a 0-byte file, so the file WAS written + // and the old "was not written within 00:00:15" message sent anyone reading it down the wrong path. + var pidFile = Path.Join(_tempDirectory.FullName, $"emptymsg_{Guid.NewGuid():N}.pid"); + await File.WriteAllTextAsync(pidFile, string.Empty, TestContext.CancellationToken); + + var ex = await Assert.ThrowsAsync( + async () => await WaitForPidFileAsync(pidFile, TimeSpan.FromMilliseconds(200), TestContext.CancellationToken)); + + StringAssert.Contains(ex.Message, "never contained a parsable PID"); + } + + [TestMethod] + public async Task TreeKillScript_WhenTheChildCannotStart_PublishesNoPidFileAtAll() + { + // Root-cause regression guard. Start-Process failure is a NON-terminating error, so without + // $ErrorActionPreference = 'Stop' the script ran on to Set-Content with a null $p and left a + // 0-byte PID file behind -- which the reader then polled until it timed out. Measured against + // the unhardened script, this produced a zero-length file every time. + // + // Driving the real script through a real PowerShell is the point: the bug lived in PowerShell's + // error semantics, so nothing short of running it can prove the behaviour. + var pidFile = Path.Join(_tempDirectory.FullName, $"nostart_{Guid.NewGuid():N}.pid"); + var script = BuildTreeKillScript(pidFile, "winapp_no_such_binary_" + Guid.NewGuid().ToString("N") + ".exe"); + + var startInfo = new ProcessStartInfo + { + FileName = "powershell.exe", + RedirectStandardOutput = true, + RedirectStandardError = true, + UseShellExecute = false, + CreateNoWindow = true, + }; + startInfo.ArgumentList.Add("-NoProfile"); + startInfo.ArgumentList.Add("-NonInteractive"); + startInfo.ArgumentList.Add("-Command"); + startInfo.ArgumentList.Add(script); + + using var process = Process.Start(startInfo)!; + var stderr = await process.StandardError.ReadToEndAsync(TestContext.CancellationToken); + await process.WaitForExitAsync(TestContext.CancellationToken); + + Assert.IsFalse( + File.Exists(pidFile), + $"A failed child start must abort the script before Set-Content, leaving no PID file to mislead the reader. stderr: {stderr}"); + Assert.AreNotEqual(0, process.ExitCode, "The script must report the failure through its exit code."); + StringAssert.Contains(stderr, "Start-Process", "The reason has to reach stderr, which is what the reader surfaces."); + } + #endregion #region RunDotnetCommandAsync cancellation (process-tree kill) diff --git a/src/winapp-CLI/WinApp.Cli.Tests/TestProcessDump.cs b/src/winapp-CLI/WinApp.Cli.Tests/TestProcessDump.cs index a48a14956..b057ef702 100644 --- a/src/winapp-CLI/WinApp.Cli.Tests/TestProcessDump.cs +++ b/src/winapp-CLI/WinApp.Cli.Tests/TestProcessDump.cs @@ -88,6 +88,15 @@ internal static class TestProcessDump /// can enumerate the CLR. Returns the dump path or null (with a reason) when not possible. /// The caller owns deleting the returned file. /// + /// + /// The child proves it is ready and the dump is taken only once that proof arrives, because a host + /// that has been started is not yet a host with a walkable CLR in it. A fixed 1.5s sleep + /// stood in for that proof and did not hold on a loaded agent: CI captured dumps whose only stack + /// was hostfxr/hostpolicy still loading coreclr, so ClrMD had nothing to enumerate, + /// the analysis reported "No CLR runtime found in dump (native-only crash)", and the managed + /// assertions failed intermittently. See for what the child + /// does before signalling and why merely reaching managed code is not enough on its own. + /// public static string? TryCreateManagedDump(out string? error) { error = null; @@ -104,6 +113,7 @@ internal static class TestProcessDump CreateNoWindow = true, RedirectStandardInput = true, RedirectStandardOutput = true, + RedirectStandardError = true, }); if (child == null) @@ -111,21 +121,19 @@ internal static class TestProcessDump continue; } - // Give the runtime time to fully spin up its heap before dumping. - Thread.Sleep(1500); - if (child.HasExited) + // Drain stderr so a chatty host can never fill the pipe and wedge the child. + var draining = child; + _ = Task.Run(() => { try { draining.StandardError.ReadToEnd(); } catch { /* ignore */ } }); + + if (!WaitForToken(child, ManagedReadyToken, TimeSpan.FromSeconds(30))) { + error = $"managed child did not emit readiness token '{ManagedReadyToken}' (host {fileName})"; + KillQuietly(child); + child = null; continue; } - var service = new CrashDumpService( - new TestConsole(), - NullLogger.Instance, - new FakeXamlTriageService()); - - var dumpPath = service.WriteMiniDump( - (uint)child.Id, savedContext: null, savedThreadId: 0, - savedExceptionCode: 0, savedExceptionAddress: 0); + var dumpPath = DumpRunningChild(child); if (dumpPath != null) { return dumpPath; @@ -137,18 +145,9 @@ internal static class TestProcessDump } finally { - try - { - if (child != null && !child.HasExited) - { - child.Kill(entireProcessTree: true); - } - - child?.Dispose(); - } - catch + if (child != null) { - // best effort + KillQuietly(child); } } } @@ -157,10 +156,37 @@ internal static class TestProcessDump return null; } + /// Readiness token the benign managed child emits once its CLR is up and its heap is warm. + private const string ManagedReadyToken = "MANAGED_READY"; + private static IEnumerable<(string FileName, string Args)> ManagedChildCandidates() { - yield return ("pwsh.exe", "-NoLogo -NoProfile -Command \"Start-Sleep -Seconds 120\""); - yield return ("powershell.exe", "-NoLogo -NoProfile -Command \"Start-Sleep -Seconds 120\""); + // The child allocates, forces a blocking collection, and only then reports readiness, so the + // token means "the runtime is up AND its heap is populated and settled" rather than merely "a + // process exists". Both halves matter and neither is decoration: + // + // - Signalling from managed code is what rules out dumping a host still in NATIVE startup. + // That was the CI failure: dumps whose only stack was hostfxr/hostpolicy loading coreclr, so + // ClrMD found no runtime and the analysis reported a native-only crash. + // - Allocating and collecting first is what rules out the opposite mistake. A token emitted by + // the first line of managed code proves too little -- ClrMD needs walkable GC structures, and + // dumping that early trades the old race for a new one (measured: signalling immediately made + // this test fail or go inconclusive on a machine where the previous code passed). + // + // [Console]::Out with an explicit Flush, not Write-Object: the token must reach the reader as + // soon as it is written, which only an unbuffered write to the real stdout handle guarantees + // once the stream is redirected. Single quotes throughout so the script survives being embedded + // in the double-quoted -Command argument. + const string script = + "$sink = 1..2000 | ForEach-Object { [pscustomobject]@{ I = $_; S = 'warm' + $_ } }; " + + "[GC]::Collect(); " + + "[GC]::WaitForPendingFinalizers(); " + + $"[Console]::Out.WriteLine('{ManagedReadyToken}'); " + + "[Console]::Out.Flush(); " + + "Start-Sleep -Seconds 120"; + + yield return ("pwsh.exe", $"-NoLogo -NoProfile -Command \"{script}\""); + yield return ("powershell.exe", $"-NoLogo -NoProfile -Command \"{script}\""); } ///