diff --git a/.github/workflows/Steeltoe.All.yml b/.github/workflows/Steeltoe.All.yml index 12b5e92a2b..9715a6c64d 100644 --- a/.github/workflows/Steeltoe.All.yml +++ b/.github/workflows/Steeltoe.All.yml @@ -139,6 +139,8 @@ jobs: ${{ github.workspace }}/TestOutput/**/*.dmp ${{ github.workspace }}/TestOutput/**/Sequence_*.xml ${{ github.workspace }}/TestOutput/**/*.binlog + ${{ github.workspace }}/TestOutput/**/*.nettrace + ${{ github.workspace }}/TestOutput/**/*.context.txt if-no-files-found: ignore - name: Report test results diff --git a/.github/workflows/component-shared-workflow.yml b/.github/workflows/component-shared-workflow.yml index b03a49315f..d39c3f5f1b 100644 --- a/.github/workflows/component-shared-workflow.yml +++ b/.github/workflows/component-shared-workflow.yml @@ -113,6 +113,8 @@ jobs: ${{ github.workspace }}/TestOutput/**/*.dmp ${{ github.workspace }}/TestOutput/**/Sequence_*.xml ${{ github.workspace }}/TestOutput/**/*.binlog + ${{ github.workspace }}/TestOutput/**/*.nettrace + ${{ github.workspace }}/TestOutput/**/*.context.txt if-no-files-found: ignore - name: Report test results diff --git a/.github/workflows/sonarcube.yml b/.github/workflows/sonarcube.yml index 4756bf118a..4ff897da87 100644 --- a/.github/workflows/sonarcube.yml +++ b/.github/workflows/sonarcube.yml @@ -131,6 +131,8 @@ jobs: ${{ github.workspace }}/TestOutput/**/*.dmp ${{ github.workspace }}/TestOutput/**/Sequence_*.xml ${{ github.workspace }}/TestOutput/**/*.binlog + ${{ github.workspace }}/TestOutput/**/*.nettrace + ${{ github.workspace }}/TestOutput/**/*.context.txt if-no-files-found: ignore - name: End Sonar .NET scanner diff --git a/src/Management/test/GitProperties.Build.Test/ProcessRunner.cs b/src/Management/test/GitProperties.Build.Test/ProcessRunner.cs index 396ed1f445..c14bbf79c0 100644 --- a/src/Management/test/GitProperties.Build.Test/ProcessRunner.cs +++ b/src/Management/test/GitProperties.Build.Test/ProcessRunner.cs @@ -2,14 +2,32 @@ // The .NET Foundation licenses this file to you under the Apache 2.0 License. // See the LICENSE file in the project root for more information. +using System.Collections; using System.Diagnostics; using System.Runtime.CompilerServices; +using System.Runtime.InteropServices; using System.Text; +using System.Text.RegularExpressions; namespace Steeltoe.Management.GitProperties.Build.Test; -internal static class ProcessRunner +internal static partial class ProcessRunner { + /// + /// The runtime provider (keyword 0x8000, informational) records every exception thrown, including handled ones. The NuGet providers emit start/stop + /// events for each phase of a restore (no-op calculation, restore graph, assets file, commit), which shows how far it got. The HTTP and DNS providers + /// show feed requests and their outcome. + /// + private static readonly string EventPipeProviders = string.Concat((string[]) + [ + "Microsoft-Windows-DotNETRuntime:0x8000:4,", + "Microsoft-NuGet-Commands:0xFFFFFFFFFFFFFFFF:5,", + "Microsoft-NuGet-Common:0xFFFFFFFFFFFFFFFF:5,", + "Microsoft-NuGet-Configuration:0xFFFFFFFFFFFFFFFF:5,", + "Microsoft-System-Net-Http:0xFFFFFFFFFFFFFFFF:4,", + "System.Net.NameResolution:0xFFFFFFFFFFFFFFFF:4" + ]); + private static readonly string LocatorCommand = OperatingSystem.IsWindows() ? "where" : "which"; private static readonly char[] LineSeparators = @@ -24,6 +42,27 @@ internal static class ProcessRunner /// private static readonly TimeSpan ProcessExitTimeout = TimeSpan.FromMinutes(2); + private static readonly string[] EnvironmentVariablePrefixes = + [ + "DOTNET_", + "CORECLR_", + "COR_", + "NUGET_", + "MSBUILD", + "TMP", + "TEMP", + "HOME" + ]; + + private static readonly string[] ProcessNamesToCapture = + [ + "dotnet", + "msbuild", + "vbcscompiler", + "testhost", + "git" + ]; + private static readonly Task RealGitExecutableTask = ResolveGitExecutableAsync(); private static readonly Task DiagnosticsDirectoryTask = ResolveDiagnosticsDirectoryAsync(); @@ -56,7 +95,18 @@ public static async Task RunDotNetBuildCapturingDiagnosticsOnFailureAsync(string params string[] arguments) { string diagnosticsDirectory = await DiagnosticsDirectoryTask; - string binlogPath = Path.Combine(diagnosticsDirectory, $"{diagnosticsFileNamePrefix}-{$"{Guid.NewGuid():N}"[..8]}.binlog"); + string diagnosticsFilePrefix = Path.Combine(diagnosticsDirectory, $"{diagnosticsFileNamePrefix}-{$"{Guid.NewGuid():N}"[..8]}"); + string binlogPath = $"{diagnosticsFilePrefix}.binlog"; + + // Records every exception thrown (including handled ones) in each spawned .NET process, which reveals failures that tasks swallow without logging + // (such as RestoreTask returning false without an error). The runtime replaces {pid} with the process ID, so each process writes its own file. + var traceEnvironmentVariables = new Dictionary + { + ["DOTNET_EnableEventPipe"] = "1", + ["DOTNET_EventPipeConfig"] = EventPipeProviders, + ["DOTNET_EventPipeOutputPath"] = $"{diagnosticsFilePrefix}.{{pid}}.nettrace", + ["DOTNET_EventPipeOutputStreaming"] = "1" + }; string[] argumentsWithBinlog = [ @@ -67,15 +117,125 @@ public static async Task RunDotNetBuildCapturingDiagnosticsOnFailureAsync(string $"-bl:{binlogPath}" ]; - await RunDotNetAsync(workingDirectory, 0, null, argumentsWithBinlog); + try + { + await RunDotNetAsync(workingDirectory, 0, traceEnvironmentVariables, argumentsWithBinlog); + } + catch (Exception) + { + await CaptureFailureContextAsync(workingDirectory, diagnosticsFilePrefix, traceEnvironmentVariables, arguments); + throw; + } + + DeleteDiagnosticsFiles(diagnosticsDirectory, Path.GetFileName(diagnosticsFilePrefix)); + } + + /// + /// Best-effort capture of information that helps to determine whether a failed build is deterministic or transient and what the machine looked like. + /// Never throws, so the original failure remains the one that is reported. + /// + private static async Task CaptureFailureContextAsync(string workingDirectory, string diagnosticsFilePrefix, + Dictionary traceEnvironmentVariables, string[] arguments) + { + var builder = new StringBuilder(); try { - File.Delete(binlogPath); + builder.AppendLine($"Captured at: {DateTimeOffset.UtcNow:O}"); + builder.AppendLine($"OS: {RuntimeInformation.OSDescription}"); + builder.AppendLine($"Processor count: {Environment.ProcessorCount}"); + + GCMemoryInfo memoryInfo = GC.GetGCMemoryInfo(); + builder.AppendLine($"Memory (available/load, bytes): {memoryInfo.TotalAvailableMemoryBytes}/{memoryInfo.MemoryLoadBytes}"); + + foreach (string path in new[] + { + Path.GetTempPath(), + workingDirectory, + Environment.GetFolderPath(Environment.SpecialFolder.UserProfile) + }.Distinct()) + { + var drive = new DriveInfo(path); + builder.AppendLine($"Free disk space on '{drive.Name}' (for '{path}'): {drive.AvailableFreeSpace} bytes"); + } + + builder.AppendLine("Environment variables:"); + + foreach (DictionaryEntry entry in Environment.GetEnvironmentVariables().Cast().OrderBy(entry => entry.Key.ToString())) + { + string name = entry.Key.ToString()!; + + if (Array.Exists(EnvironmentVariablePrefixes, prefix => name.StartsWith(prefix, StringComparison.OrdinalIgnoreCase))) + { + string sanitizedValue = SanitizeEnvironmentVariable(name, entry.Value); + builder.AppendLine($" {name}={sanitizedValue}"); + } + } + + builder.AppendLine("Related processes still running:"); + + foreach (Process process in Process.GetProcesses().OrderBy(process => process.Id)) + { + using (process) + { + if (Array.Exists(ProcessNamesToCapture, name => process.ProcessName.Contains(name, StringComparison.OrdinalIgnoreCase))) + { + builder.AppendLine($" {process.Id} {process.ProcessName}"); + } + } + } + + // Determines whether the failure reproduces right away. A restore that now succeeds points to a transient (timing/concurrency) cause. A restore + // that fails again leaves a second binlog and trace, captured against the very same state on disk. + string[] restoreArguments = + [ + "restore", + .. arguments, + $"-bl:{diagnosticsFilePrefix}.retry-restore.binlog" + ]; + + try + { + Dictionary retryEnvironmentVariables = new(traceEnvironmentVariables) + { + ["DOTNET_EventPipeOutputPath"] = $"{diagnosticsFilePrefix}.retry-restore.{{pid}}.nettrace" + }; + + string output = await RunDotNetAsync(workingDirectory, 0, retryEnvironmentVariables, restoreArguments); + builder.AppendLine("Retrying restore succeeded. Output:"); + builder.AppendLine(output); + } + catch (Exception exception) + { + builder.AppendLine("Retrying restore failed:"); + builder.AppendLine(exception.ToString()); + } + } + catch (Exception exception) + { + builder.AppendLine($"Failed to capture all context: {exception}"); } - catch (Exception exception) when (exception is IOException or UnauthorizedAccessException) + + await File.WriteAllTextAsync($"{diagnosticsFilePrefix}.context.txt", builder.ToString(), CancellationToken.None); + } + + private static string SanitizeEnvironmentVariable(string name, object? value) + { + return SensitiveVariableRegex().IsMatch(name) ? "******" : value?.ToString() ?? string.Empty; + } + + private static void DeleteDiagnosticsFiles(string diagnosticsDirectory, string fileNamePrefix) + { + foreach (string path in Directory.EnumerateFiles(diagnosticsDirectory, $"{fileNamePrefix}.*")) { - // Best-effort cleanup only: a transiently locked file (e.g. an antivirus scan) must not fail the test run. + try + { + File.Delete(path); + } + catch (Exception exception) when (exception is IOException or UnauthorizedAccessException) + { + // Best-effort cleanup only: a transiently locked file (e.g. an antivirus scan, or a lingering build server) must not fail the test run. + } } } @@ -106,6 +266,9 @@ public static Task RunDotNetAsync(string workingDirectory, int exitCodeE // never sees EOF and awaiting exit below would block forever even though the build already completed successfully. dotNetEnvironmentVariables["MSBUILDDISABLENODEREUSE"] = "1"; + // Include stack traces when NuGet reports an exception, so that otherwise opaque restore failures (such as MSB4181) become diagnosable. + dotNetEnvironmentVariables["NUGET_SHOW_STACK"] = "true"; + foreach ((string name, string value) in environmentVariables ?? []) { dotNetEnvironmentVariables[name] = value; @@ -227,4 +390,7 @@ private static void KillEntireProcessTreeInBackground(int processId) } }); } + + [GeneratedRegex("password|secret|key|token|credential", RegexOptions.IgnoreCase | RegexOptions.CultureInvariant)] + private static partial Regex SensitiveVariableRegex(); }