From f22daabcae8be07a1baa34091818270ff1cc5581 Mon Sep 17 00:00:00 2001 From: Tyrie Vella Date: Thu, 27 Aug 2026 09:44:02 -0700 Subject: [PATCH] FunctionalTests: capture mount dumps and preserve logs on failure When a functional test fails because its GVFS.Mount is unreachable (a hang or silent exit), we currently have no post-mortem data. Per-test enlistment inlined into the console by TestResultsHelper.OutputGVFSLogs -- lossy under parallel fixtures and empty when the mount hung. There is no process dump, so a mount deadlock leaves zero diagnostic signal. On test failure only, into a CI-uploadable diagnostics directory: GVFSFunctionalTestEnlistment.CaptureFailureDiagnostics runs first in DeleteEnlistment, gated on TestStatus.Failed, before the enlistment directory is deleted. The mount-process PID discovery is extracted from KillMountProcess into a shared GetMountProcessIds helper. CI: functional-tests.yaml sets GVFS_TEST_DIAGNOSTICS_DIR and uploads it as a FailureDiagnostics artifact with if: always(). Review follow-ups: - GetMountProcessIds doubled the backslashes in the enlistment path before using it in a PowerShell -like wildcard. In -like, '\' is a literal (not an escape), so the doubled pattern never matched a real single-backslash command line: CaptureFailureDiagnostics found no live mount and wrote no minidump, and KillMountProcess silently killed nothing. Match on the enlistment's unique leaf folder id instead -- present on the GVFS.Mount command line (launched with PrimaryEnlistmentRoot), unique, and free of path separators or wildcard metacharacters, so it needs no escaping. - WaitForExit(int) only guarantees the helper process has exited -- it does not guarantee the async OutputDataReceived callbacks (raised on the thread pool as data arrives) have all run yet. Reading the output buffer immediately afterward could race the last callback and intermittently drop a trailing PID, making GetMountProcessIds miss a live mount process. Call the parameterless WaitForExit() right after the timed wait succeeds to drain any pending async output callbacks before parsing. Assisted-by: Claude Sonnet 5 Signed-off-by: Tyrie Vella --- .github/workflows/functional-tests.yaml | 10 + .../Tests/TestResultsHelper.cs | 83 ++++++++ .../Tools/GVFSFunctionalTestEnlistment.cs | 190 ++++++++++++++++-- GVFS/GVFS.FunctionalTests/Tools/MiniDump.cs | 88 ++++++++ 4 files changed, 357 insertions(+), 14 deletions(-) create mode 100644 GVFS/GVFS.FunctionalTests/Tools/MiniDump.cs diff --git a/.github/workflows/functional-tests.yaml b/.github/workflows/functional-tests.yaml index 60f61d3088..7274f97656 100644 --- a/.github/workflows/functional-tests.yaml +++ b/.github/workflows/functional-tests.yaml @@ -204,8 +204,18 @@ jobs: run: | SET PATH=C:\Program Files\VFS for Git;%PATH% SET GIT_TRACE2_PERF=C:\temp\git-trace2.log + SET GVFS_TEST_DIAGNOSTICS_DIR=C:\temp\gvfs-ft-diagnostics ft\GVFS.FunctionalTests.exe /result:TestResult.xml --ci --slice=${{ matrix.nr }},12 + - name: Upload failure diagnostics (mount dumps + logs) + if: always() && steps.skip.outputs.result != 'true' + uses: actions/upload-artifact@v7 + continue-on-error: true + with: + name: ${{ env.ARTIFACT_PREFIX }}FailureDiagnostics_${{ env.FT_MATRIX_NAME }} + path: C:\temp\gvfs-ft-diagnostics + if-no-files-found: ignore + - name: Upload functional test results if: always() && steps.skip.outputs.result != 'true' uses: actions/upload-artifact@043fb46d1a93c77aae656e7c1c64a875d1fc6a0a # v7.0.1 diff --git a/GVFS/GVFS.FunctionalTests/Tests/TestResultsHelper.cs b/GVFS/GVFS.FunctionalTests/Tests/TestResultsHelper.cs index e70adca78d..3c197a1ecd 100644 --- a/GVFS/GVFS.FunctionalTests/Tests/TestResultsHelper.cs +++ b/GVFS/GVFS.FunctionalTests/Tests/TestResultsHelper.cs @@ -69,5 +69,88 @@ public static IEnumerable GetAllFilesInDirectory(string folderName) return directory.GetFiles().Select(file => file.FullName); } + + /// + /// Root directory under which per-failure diagnostics (preserved logs and + /// mount process dumps) are written so CI can upload them as an artifact. + /// Honors the GVFS_TEST_DIAGNOSTICS_DIR environment variable; otherwise + /// falls back to a folder under the temp path. + /// + public static string DiagnosticsRoot + { + get + { + string configured = Environment.GetEnvironmentVariable("GVFS_TEST_DIAGNOSTICS_DIR"); + return string.IsNullOrWhiteSpace(configured) + ? Path.Combine(Path.GetTempPath(), "gvfs_ft_diagnostics") + : configured; + } + } + + /// + /// Copies every file in into + /// . A mount that hung or exited + /// abnormally may still hold its log file open, so a plain copy can fail + /// with a sharing violation. In that case we fall back to opening the file + /// with a read-only shared handle (FileShare.ReadWrite | Delete) and copy + /// out whatever has been flushed so far — partial content is still useful. + /// Best-effort: never throws. + /// + public static void CopyFilesWithFallback(string sourceFolder, string destinationFolder) + { + try + { + Directory.CreateDirectory(destinationFolder); + } + catch (Exception ex) + { + Console.Error.WriteLine($"[DIAGNOSTICS] Unable to create '{destinationFolder}': {ex.Message}"); + return; + } + + foreach (string sourceFile in GetAllFilesInDirectory(sourceFolder)) + { + string destinationFile = Path.Combine(destinationFolder, Path.GetFileName(sourceFile)); + + try + { + File.Copy(sourceFile, destinationFile, overwrite: true); + } + catch (Exception copyException) when (copyException is IOException || copyException is UnauthorizedAccessException) + { + // The file is likely locked by a still-running (possibly hung) + // mount process. Fall back to a shared read-only handle and copy + // what we can. + if (!TryCopyWithSharedReadHandle(sourceFile, destinationFile)) + { + Console.Error.WriteLine($"[DIAGNOSTICS] Failed to copy '{sourceFile}' (locked): {copyException.Message}"); + } + } + catch (Exception ex) + { + Console.Error.WriteLine($"[DIAGNOSTICS] Failed to copy '{sourceFile}': {ex.Message}"); + } + } + } + + private static bool TryCopyWithSharedReadHandle(string sourceFile, string destinationFile) + { + try + { + using (FileStream source = new FileStream(sourceFile, FileMode.Open, FileAccess.Read, FileShare.ReadWrite | FileShare.Delete)) + using (FileStream destination = new FileStream(destinationFile, FileMode.Create, FileAccess.Write, FileShare.None)) + { + source.CopyTo(destination); + } + + Console.Error.WriteLine($"[DIAGNOSTICS] Copied '{sourceFile}' via shared read handle (may be partial)"); + return true; + } + catch (Exception ex) + { + Console.Error.WriteLine($"[DIAGNOSTICS] Shared-handle copy of '{sourceFile}' failed: {ex.Message}"); + return false; + } + } } } diff --git a/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs b/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs index 4d653f7e23..d352a53191 100644 --- a/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs +++ b/GVFS/GVFS.FunctionalTests/Tools/GVFSFunctionalTestEnlistment.cs @@ -2,6 +2,8 @@ using GVFS.FunctionalTests.Should; using GVFS.FunctionalTests.Tests; using GVFS.Tests.Should; +using NUnit.Framework; +using NUnit.Framework.Interfaces; using System; using System.Collections.Generic; using System.IO; @@ -179,10 +181,102 @@ public string GetPackRoot(FileSystemRunner fileSystem) public void DeleteEnlistment() { + this.CaptureFailureLogs(); TestResultsHelper.OutputGVFSLogs(this); RepositoryHelpers.DeleteTestDirectory(this.EnlistmentRoot); } + /// + /// When the current test has failed, writes a full-memory minidump of each still-running + /// GVFS.Mount process for this enlistment, so a mount *hang* can be diagnosed after the fact. + /// Must be called before the mount is unmounted or killed - once the process is gone (whether + /// cleanly unmounted or force-killed) there is nothing left to dump. Written under + /// so CI can upload it. Best-effort: never + /// throws, so it cannot break teardown. + /// + public void CaptureFailureDiagnostics() + { + try + { + if (!this.TryGetFailureDiagnosticsFolder(out string destinationFolder)) + { + return; + } + + List mountProcessIds = this.GetMountProcessIds(); + if (mountProcessIds.Count == 0) + { + Console.Error.WriteLine("[DIAGNOSTICS] No live GVFS.Mount process for this enlistment (already exited/crashed)"); + return; + } + + Console.Error.WriteLine($"[DIAGNOSTICS] Test failed; capturing mount dump(s) to '{destinationFolder}'"); + Directory.CreateDirectory(destinationFolder); + foreach (int pid in mountProcessIds) + { + MiniDump.TryWrite(pid, Path.Combine(destinationFolder, $"GVFS.Mount_{pid}.dmp")); + } + } + catch (Exception ex) + { + Console.Error.WriteLine($"[DIAGNOSTICS] CaptureFailureDiagnostics failed: {ex.Message}"); + } + } + + /// + /// When the current test has failed, preserves the enlistment's .gvfs/logs folder (robust to + /// locked / partially-flushed files) under + /// before the enlistment directory is deleted. Best-effort: never throws. + /// + private void CaptureFailureLogs() + { + try + { + if (!this.TryGetFailureDiagnosticsFolder(out string destinationFolder)) + { + return; + } + + Console.Error.WriteLine($"[DIAGNOSTICS] Test failed; capturing logs to '{destinationFolder}'"); + TestResultsHelper.CopyFilesWithFallback(this.GVFSLogsRoot, Path.Combine(destinationFolder, "logs")); + } + catch (Exception ex) + { + Console.Error.WriteLine($"[DIAGNOSTICS] CaptureFailureLogs failed: {ex.Message}"); + } + } + + private bool TryGetFailureDiagnosticsFolder(out string destinationFolder) + { + destinationFolder = null; + if (TestContext.CurrentContext.Result.Outcome.Status != TestStatus.Failed) + { + return false; + } + + destinationFolder = Path.Combine( + TestResultsHelper.DiagnosticsRoot, + SanitizeForPath(TestContext.CurrentContext.Test.Name) + "_" + Path.GetFileName(this.EnlistmentRoot)); + return true; + } + + private static string SanitizeForPath(string name) + { + if (string.IsNullOrEmpty(name)) + { + return "test"; + } + + foreach (char invalid in Path.GetInvalidFileNameChars()) + { + name = name.Replace(invalid, '_'); + } + + // Flatten characters that are legal in file names but noisy in NUnit + // test names (parameterized cases, spaces). + return name.Replace('(', '_').Replace(')', '_').Replace(' ', '_').Replace(',', '_').Replace('"', '_'); + } + public void CloneAndMount(bool skipPrefetch) { Console.Error.WriteLine("[CI-DEBUG] CloneAndMount: starting clone of " + this.RepoUrl); @@ -303,6 +397,10 @@ public string SetCacheServer(string arg) public void UnmountAndDeleteAll() { + // Capture the mount dump before unmounting or killing anything - once the mount process is + // gone (whether it unmounts cleanly or is force-killed below) there is nothing left to dump. + this.CaptureFailureDiagnostics(); + try { this.UnmountGVFS(); @@ -320,12 +418,39 @@ public void UnmountAndDeleteAll() public void KillMountProcess() { + foreach (int pid in this.GetMountProcessIds()) + { + Console.Error.WriteLine($"[TEARDOWN] Killing GVFS.Mount (PID {pid}) for {this.EnlistmentRoot}"); + try + { + System.Diagnostics.Process.GetProcessById(pid)?.Kill(); + } + catch (Exception ex) + { + Console.Error.WriteLine($"[TEARDOWN] Failed to kill PID {pid}: {ex.Message}"); + } + } + } + + /// + /// Returns the process ids of the GVFS.Mount processes whose command line + /// references this enlistment root. Uses PowerShell's Get-CimInstance to + /// read command lines without requiring System.Management. Best-effort: + /// returns an empty list on any failure (e.g. non-Windows). + /// + private List GetMountProcessIds() + { + List processIds = new List(); + try { - // Find GVFS.Mount processes whose command line contains this - // enlistment root. Uses PowerShell's Get-CimInstance to read - // command lines without requiring System.Management. - string filter = this.EnlistmentRoot.Replace("\\", "\\\\"); + // Match on the enlistment's unique leaf folder id rather than the + // full path. PowerShell's -like treats '\' as a literal (not an + // escape), so doubling backslashes in the full path would produce a + // pattern that never matches a real (single-backslash) command line. + // The leaf id is unique and free of path separators and wildcard + // metacharacters, so it needs no escaping. + string filter = Path.GetFileName(this.EnlistmentRoot.TrimEnd('\\', '/')); var psi = new System.Diagnostics.ProcessStartInfo("powershell.exe") { Arguments = $"-NoProfile -Command \"Get-CimInstance Win32_Process -Filter \\\"Name='GVFS.Mount.exe'\\\" | Where-Object {{ $_.CommandLine -like '*{filter}*' }} | ForEach-Object {{ $_.ProcessId }}\"", @@ -333,30 +458,67 @@ public void KillMountProcess() UseShellExecute = false, CreateNoWindow = true, }; - var proc = System.Diagnostics.Process.Start(psi); - string output = proc.StandardOutput.ReadToEnd(); - proc.WaitForExit(10000); - foreach (string line in output.Split('\n', StringSplitOptions.RemoveEmptyEntries)) + var output = new System.Text.StringBuilder(); + + // Read output asynchronously via the event, rather than a blocking ReadToEnd() before + // WaitForExit(): ReadToEnd() blocks until the process closes its stdout handle, so if the + // helper itself hangs, the later WaitForExit(10000) timeout is never reached at all. With + // async reads, WaitForExit is the only blocking call, so it enforces a real timeout and we + // can kill the helper if it does not exit in time. + using (var proc = new System.Diagnostics.Process { StartInfo = psi }) { - if (int.TryParse(line.Trim(), out int pid)) + proc.OutputDataReceived += (sender, args) => { - Console.Error.WriteLine($"[TEARDOWN] Killing GVFS.Mount (PID {pid}) for {this.EnlistmentRoot}"); + if (args.Data != null) + { + output.AppendLine(args.Data); + } + }; + + proc.Start(); + proc.BeginOutputReadLine(); + + if (!proc.WaitForExit(10000)) + { + Console.Error.WriteLine("[TEARDOWN] GetMountProcessIds helper timed out; killing it"); try { - System.Diagnostics.Process.GetProcessById(pid)?.Kill(); + proc.Kill(); + proc.WaitForExit(2000); } - catch (Exception ex) + catch (Exception killEx) { - Console.Error.WriteLine($"[TEARDOWN] Failed to kill PID {pid}: {ex.Message}"); + Console.Error.WriteLine($"[TEARDOWN] Failed to kill GetMountProcessIds helper: {killEx.Message}"); } } + else + { + // WaitForExit(int) only guarantees the process has exited - it does NOT guarantee + // that all queued OutputDataReceived callbacks have run yet, since those fire on + // the thread pool as data arrives. Reading `output` right here could race the last + // callback(s) and silently drop a trailing PID line. The parameterless WaitForExit() + // is documented to block until the redirected stream's async reads have completed, + // so calling it again (a no-op once the process has exited) drains any pending + // callbacks before we parse output below. + proc.WaitForExit(); + } + } + + foreach (string line in output.ToString().Split('\n', StringSplitOptions.RemoveEmptyEntries)) + { + if (int.TryParse(line.Trim(), out int pid)) + { + processIds.Add(pid); + } } } catch (Exception ex) { - Console.Error.WriteLine($"[TEARDOWN] KillMountProcess failed: {ex.Message}"); + Console.Error.WriteLine($"[TEARDOWN] GetMountProcessIds failed: {ex.Message}"); } + + return processIds; } public string GetVirtualPathTo(string path) diff --git a/GVFS/GVFS.FunctionalTests/Tools/MiniDump.cs b/GVFS/GVFS.FunctionalTests/Tools/MiniDump.cs new file mode 100644 index 0000000000..57356f44cd --- /dev/null +++ b/GVFS/GVFS.FunctionalTests/Tools/MiniDump.cs @@ -0,0 +1,88 @@ +using System; +using System.Diagnostics; +using System.IO; +using System.Runtime.InteropServices; + +namespace GVFS.FunctionalTests.Tools +{ + /// + /// Best-effort process minidump writer used to capture post-mortem state of a + /// (potentially hung) GVFS.Mount process when a functional test fails. Windows + /// only; a no-op that returns false on other platforms. Never throws. + /// + public static class MiniDump + { + [Flags] + private enum MiniDumpType : uint + { + Normal = 0x00000000, + WithFullMemory = 0x00000002, + WithHandleData = 0x00000004, + WithFullMemoryInfo = 0x00000800, + WithThreadInfo = 0x00001000, + } + + /// + /// Writes a full-memory minidump of the process with the given id to + /// . A full-memory dump is required so + /// that managed call stacks are resolvable in WinDbg/SOS, which is what we + /// need to diagnose a mount deadlock. Returns true on success. + /// + public static bool TryWrite(int processId, string destinationPath) + { + if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows)) + { + Console.Error.WriteLine($"[DIAGNOSTICS] MiniDump skipped (non-Windows) for PID {processId}"); + return false; + } + + try + { + using (Process process = Process.GetProcessById(processId)) + using (FileStream dumpFile = new FileStream(destinationPath, FileMode.Create, FileAccess.ReadWrite, FileShare.Write)) + { + MiniDumpType dumpType = + MiniDumpType.WithFullMemory | + MiniDumpType.WithHandleData | + MiniDumpType.WithThreadInfo | + MiniDumpType.WithFullMemoryInfo; + + bool succeeded = MiniDumpWriteDump( + process.Handle, + (uint)process.Id, + dumpFile.SafeFileHandle, + dumpType, + IntPtr.Zero, + IntPtr.Zero, + IntPtr.Zero); + + if (!succeeded) + { + int error = Marshal.GetLastWin32Error(); + Console.Error.WriteLine($"[DIAGNOSTICS] MiniDumpWriteDump failed for PID {processId} (Win32 error {error})"); + return false; + } + + Console.Error.WriteLine($"[DIAGNOSTICS] Wrote minidump for GVFS.Mount PID {processId} to {destinationPath}"); + return true; + } + } + catch (Exception ex) + { + Console.Error.WriteLine($"[DIAGNOSTICS] Failed to write minidump for PID {processId}: {ex.Message}"); + return false; + } + } + + [DllImport("dbghelp.dll", SetLastError = true)] + [return: MarshalAs(UnmanagedType.Bool)] + private static extern bool MiniDumpWriteDump( + IntPtr hProcess, + uint processId, + SafeHandle hFile, + MiniDumpType dumpType, + IntPtr exceptionParam, + IntPtr userStreamParam, + IntPtr callbackParam); + } +}