C#: Parallelize restore logic of missing packages

csharp/autobuilder/Semmle.Autobuild.Shared/Autobuilder.cs

@@ -267,7 +267,7 @@ protected string RequireEnvironmentVariable(string name)
 
         protected DiagnosticClassifier DiagnosticClassifier { get; }
 
-        private readonly ILogger logger = new ConsoleLogger(Verbosity.Info);
+        private readonly ILogger logger = new ConsoleLogger(Verbosity.Info, logThreadId: false);
 
         private readonly IDiagnosticsWriter diagnostics;
 

csharp/autobuilder/Semmle.Autobuild.Shared/BuildActions.cs

@@ -187,12 +187,12 @@ public class SystemBuildActions : IBuildActions
 
         bool IBuildActions.FileExists(string file) => File.Exists(file);
 
-        private static ProcessStartInfo GetProcessStartInfo(string exe, string arguments, string? workingDirectory, IDictionary<string, string>? environment, bool redirectStandardOutput)
+        private static ProcessStartInfo GetProcessStartInfo(string exe, string arguments, string? workingDirectory, IDictionary<string, string>? environment)
         {
             var pi = new ProcessStartInfo(exe, arguments)
             {
                 UseShellExecute = false,
-                RedirectStandardOutput = redirectStandardOutput
+                RedirectStandardOutput = true
             };
             if (workingDirectory is not null)
                 pi.WorkingDirectory = workingDirectory;
@@ -204,40 +204,22 @@ private static ProcessStartInfo GetProcessStartInfo(string exe, string arguments
 
         int IBuildActions.RunProcess(string exe, string args, string? workingDirectory, System.Collections.Generic.IDictionary<string, string>? env, BuildOutputHandler onOutput, BuildOutputHandler onError)
         {
-            var pi = GetProcessStartInfo(exe, args, workingDirectory, env, true);
-            using var p = new Process
-            {
-                StartInfo = pi
-            };
-            p.StartInfo.RedirectStandardError = true;
-            p.OutputDataReceived += new DataReceivedEventHandler((sender, e) => onOutput(e.Data));
-            p.ErrorDataReceived += new DataReceivedEventHandler((sender, e) => onError(e.Data));
-
-            p.Start();
+            var pi = GetProcessStartInfo(exe, args, workingDirectory, env);
+            pi.RedirectStandardError = true;
 
-            p.BeginErrorReadLine();
-            p.BeginOutputReadLine();
-
-            p.WaitForExit();
-            return p.ExitCode;
+            return pi.ReadOutput(out _, onOut: s => onOutput(s), onError: s => onError(s));
         }
 
         int IBuildActions.RunProcess(string cmd, string args, string? workingDirectory, IDictionary<string, string>? environment)
         {
-            var pi = GetProcessStartInfo(cmd, args, workingDirectory, environment, false);
-            using var p = Process.Start(pi);
-            if (p is null)
-            {
-                return -1;
-            }
-            p.WaitForExit();
-            return p.ExitCode;
+            var pi = GetProcessStartInfo(cmd, args, workingDirectory, environment);
+            return pi.ReadOutput(out _, onOut: Console.WriteLine, onError: null);
         }
 
         int IBuildActions.RunProcess(string cmd, string args, string? workingDirectory, IDictionary<string, string>? environment, out IList<string> stdOut)
         {
-            var pi = GetProcessStartInfo(cmd, args, workingDirectory, environment, true);
-            return pi.ReadOutput(out stdOut);
+            var pi = GetProcessStartInfo(cmd, args, workingDirectory, environment);
+            return pi.ReadOutput(out stdOut, onOut: null, onError: null);
         }
 
         void IBuildActions.DirectoryDelete(string dir, bool recursive) => Directory.Delete(dir, recursive);

csharp/extractor/Semmle.Extraction.CIL.Driver/Program.cs

@@ -38,7 +38,7 @@ public static void Main(string[] args)
             }
 
             var options = new ExtractorOptions(args);
-            using var logger = new ConsoleLogger(options.Verbosity);
+            using var logger = new ConsoleLogger(options.Verbosity, logThreadId: false);
 
             var actions = options.AssembliesToExtract
                 .Select(asm => asm.Filename)

csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DependencyManager.cs

@@ -219,7 +219,7 @@ private void GenerateSourceFilesFromWebViews(List<FileInfo> allFiles)
             }
         }
 
-        public DependencyManager(string srcDir) : this(srcDir, DependencyOptions.Default, new ConsoleLogger(Verbosity.Info)) { }
+        public DependencyManager(string srcDir) : this(srcDir, DependencyOptions.Default, new ConsoleLogger(Verbosity.Info, logThreadId: true)) { }
 
         private IEnumerable<FileInfo> GetAllFiles()
         {
@@ -430,8 +430,8 @@ private void AnalyseProject(FileInfo project)
 
         }
 
-        private bool RestoreProject(string project, out string stdout, string? pathToNugetConfig = null) =>
-            dotnet.RestoreProjectToDirectory(project, packageDirectory.DirInfo.FullName, out stdout, pathToNugetConfig);
+        private bool RestoreProject(string project, string? pathToNugetConfig = null) =>
+            dotnet.RestoreProjectToDirectory(project, packageDirectory.DirInfo.FullName, pathToNugetConfig);
 
         private bool RestoreSolution(string solution, out IEnumerable<string> projects) =>
             dotnet.RestoreSolutionToDirectory(solution, packageDirectory.DirInfo.FullName, out projects);
@@ -454,25 +454,14 @@ private IEnumerable<string> RestoreSolutions(IEnumerable<string> solutions) =>
         /// <summary>
         /// Executes `dotnet restore` on all projects in projects.
         /// This is done in parallel for performance reasons.
-        /// To ensure that output is not interleaved, the output of each
-        /// restore is collected and printed.
         /// </summary>
         /// <param name="projects">A list of paths to project files.</param>
         private void RestoreProjects(IEnumerable<string> projects)
         {
-            var stdoutLines = projects
-                .AsParallel()
-                .WithDegreeOfParallelism(options.Threads)
-                .Select(project =>
-                    {
-                        RestoreProject(project, out var stdout);
-                        return stdout;
-                    })
-                .ToList();
-            foreach (var line in stdoutLines)
+            Parallel.ForEach(projects, new ParallelOptions { MaxDegreeOfParallelism = options.Threads }, project =>
             {
-                Console.WriteLine(line);
-            }
+                RestoreProject(project);
+            });
         }
 
         private void DownloadMissingPackages(List<FileInfo> allFiles)
@@ -499,30 +488,30 @@ private void DownloadMissingPackages(List<FileInfo> allFiles)
             var alreadyDownloadedPackages = Directory.GetDirectories(packageDirectory.DirInfo.FullName)
                 .Select(d => Path.GetFileName(d).ToLowerInvariant());
             var notYetDownloadedPackages = fileContent.AllPackages.Except(alreadyDownloadedPackages);
-            foreach (var package in notYetDownloadedPackages)
+
+            Parallel.ForEach(notYetDownloadedPackages, new ParallelOptions { MaxDegreeOfParallelism = options.Threads }, package =>
             {
                 progressMonitor.NugetInstall(package);
-                using var tempDir = new TemporaryDirectory(GetTemporaryWorkingDirectory(package));
+                using var tempDir = new TemporaryDirectory(ComputeTempDirectory(package));
                 var success = dotnet.New(tempDir.DirInfo.FullName);
                 if (!success)
                 {
-                    continue;
+                    return;
                 }
+
                 success = dotnet.AddPackage(tempDir.DirInfo.FullName, package);
                 if (!success)
                 {
-                    continue;
+                    return;
                 }
 
-                success = RestoreProject(tempDir.DirInfo.FullName, out var stdout, nugetConfig);
-                Console.WriteLine(stdout);
-
+                success = RestoreProject(tempDir.DirInfo.FullName, nugetConfig);
                 // TODO: the restore might fail, we could retry with a prerelease (*-* instead of *) version of the package.
                 if (!success)
                 {
                     progressMonitor.FailedToRestoreNugetPackage(package);
                 }
-            }
+            });
         }
 
         private void AnalyseSolutions(IEnumerable<string> solutions)

csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DotNet.cs

@@ -40,16 +40,15 @@ private void Info()
         private static string GetRestoreArgs(string projectOrSolutionFile, string packageDirectory) =>
             $"restore --no-dependencies \"{projectOrSolutionFile}\" --packages \"{packageDirectory}\" /p:DisableImplicitNuGetFallbackFolder=true";
 
-        public bool RestoreProjectToDirectory(string projectFile, string packageDirectory, out string stdout, string? pathToNugetConfig = null)
+        public bool RestoreProjectToDirectory(string projectFile, string packageDirectory, string? pathToNugetConfig = null)
         {
             var args = GetRestoreArgs(projectFile, packageDirectory);
             if (pathToNugetConfig != null)
             {
                 args += $" --configfile \"{pathToNugetConfig}\"";
             }
-            var success = dotnetCliInvoker.RunCommand(args, out var output);
-            stdout = string.Join("\n", output);
-            return success;
+
+            return dotnetCliInvoker.RunCommand(args);
         }
 
         public bool RestoreSolutionToDirectory(string solutionFile, string packageDirectory, out IEnumerable<string> projects)
@@ -90,7 +89,6 @@ private IList<string> GetListed(string args, string artifact)
         {
             if (dotnetCliInvoker.RunCommand(args, out var artifacts))
             {
-                progressMonitor.LogInfo($"Found {artifact}s: {string.Join("\n", artifacts)}");
                 return artifacts;
             }
             return new List<string>();

csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DotNetCliInvoker.cs

@@ -1,3 +1,4 @@
+using System;
 using System.Collections.Generic;
 using System.Diagnostics;
 using Semmle.Util;
@@ -19,23 +20,33 @@ public DotNetCliInvoker(ProgressMonitor progressMonitor, string exec)
             this.Exec = exec;
         }
 
-        private ProcessStartInfo MakeDotnetStartInfo(string args, bool redirectStandardOutput)
+        private ProcessStartInfo MakeDotnetStartInfo(string args)
         {
             var startInfo = new ProcessStartInfo(Exec, args)
             {
                 UseShellExecute = false,
-                RedirectStandardOutput = redirectStandardOutput
+                RedirectStandardOutput = true,
+                RedirectStandardError = true
             };
             // Set the .NET CLI language to English to avoid localized output.
             startInfo.EnvironmentVariables["DOTNET_CLI_UI_LANGUAGE"] = "en";
             return startInfo;
         }
 
-        private bool RunCommandAux(string args, bool redirectStandardOutput, out IList<string> output)
+        private bool RunCommandAux(string args, out IList<string> output)
         {
             progressMonitor.RunningProcess($"{Exec} {args}");
-            var pi = MakeDotnetStartInfo(args, redirectStandardOutput);
-            var exitCode = pi.ReadOutput(out output);
+            var pi = MakeDotnetStartInfo(args);
+            var threadId = $"[{Environment.CurrentManagedThreadId:D3}]";
+            void onOut(string s)
+            {
+                Console.Out.WriteLine($"{threadId} {s}");
+            }
+            void onError(string s)
+            {
+                Console.Error.WriteLine($"{threadId} {s}");
+            }
+            var exitCode = pi.ReadOutput(out output, onOut, onError);
             if (exitCode != 0)
             {
                 progressMonitor.CommandFailed(Exec, args, exitCode);
@@ -45,9 +56,9 @@ private bool RunCommandAux(string args, bool redirectStandardOutput, out IList<s
         }
 
         public bool RunCommand(string args) =>
-            RunCommandAux(args, redirectStandardOutput: false, out _);
+            RunCommandAux(args, out _);
 
         public bool RunCommand(string args, out IList<string> output) =>
-            RunCommandAux(args, redirectStandardOutput: true, out output);
+            RunCommandAux(args, out output);
     }
 }

csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/IDotNet.cs

@@ -4,7 +4,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching
 {
     internal interface IDotNet
     {
-        bool RestoreProjectToDirectory(string project, string directory, out string stdout, string? pathToNugetConfig = null);
+        bool RestoreProjectToDirectory(string project, string directory, string? pathToNugetConfig = null);
         bool RestoreSolutionToDirectory(string solutionFile, string packageDirectory, out IEnumerable<string> projects);
         bool New(string folder);
         bool AddPackage(string folder, string package);

csharp/extractor/Semmle.Extraction.CSharp.Standalone/Extractor.cs

@@ -119,7 +119,7 @@ public static ExitCode Run(Options options)
             var stopwatch = new Stopwatch();
             stopwatch.Start();
 
-            using var logger = new ConsoleLogger(options.Verbosity);
+            using var logger = new ConsoleLogger(options.Verbosity, logThreadId: true);
             logger.Log(Severity.Info, "Running C# standalone extractor");
             using var a = new Analysis(logger, options);
             var sourceFileCount = a.Extraction.Sources.Count;

csharp/extractor/Semmle.Extraction.CSharp.Standalone/Options.cs

@@ -2,6 +2,7 @@
 using Semmle.Util;
 using Semmle.Util.Logging;
 using Semmle.Extraction.CSharp.DependencyFetching;
+using System;
 
 namespace Semmle.Extraction.CSharp.Standalone
 {
@@ -64,15 +65,15 @@ public override bool HandleArgument(string arg)
             var fi = new FileInfo(dependencies.SolutionFile);
             if (!fi.Exists)
             {
-                System.Console.WriteLine("Error: The solution {0} does not exist", fi.FullName);
+                System.Console.WriteLine($"[{Environment.CurrentManagedThreadId:D3}] Error: The solution {fi.FullName} does not exist");
                 Errors = true;
             }
             return true;
         }
 
         public override void InvalidArgument(string argument)
         {
-            System.Console.WriteLine($"Error: Invalid argument {argument}");
+            System.Console.WriteLine($"[{Environment.CurrentManagedThreadId:D3}] Error: Invalid argument {argument}");
             Errors = true;
         }
 

csharp/extractor/Semmle.Extraction.CSharp/Extractor/Extractor.cs

@@ -71,9 +71,9 @@ public static void SetInvariantCulture()
 
         public static ILogger MakeLogger(Verbosity verbosity, bool includeConsole)
         {
-            var fileLogger = new FileLogger(verbosity, GetCSharpLogPath());
+            var fileLogger = new FileLogger(verbosity, GetCSharpLogPath(), logThreadId: true);
             return includeConsole
-                ? new CombinedLogger(new ConsoleLogger(verbosity), fileLogger)
+                ? new CombinedLogger(new ConsoleLogger(verbosity, logThreadId: true), fileLogger)
                 : (ILogger)fileLogger;
         }
 

csharp/extractor/Semmle.Extraction.Tests/DotNet.cs

@@ -99,7 +99,7 @@ public void TestDotnetRestoreProjectToDirectory1()
             var dotnet = MakeDotnet(dotnetCliInvoker);
 
             // Execute
-            dotnet.RestoreProjectToDirectory("myproject.csproj", "mypackages", out var _);
+            dotnet.RestoreProjectToDirectory("myproject.csproj", "mypackages");
 
             // Verify
             var lastArgs = dotnetCliInvoker.GetLastArgs();
@@ -114,7 +114,7 @@ public void TestDotnetRestoreProjectToDirectory2()
             var dotnet = MakeDotnet(dotnetCliInvoker);
 
             // Execute
-            dotnet.RestoreProjectToDirectory("myproject.csproj", "mypackages", out var _, "myconfig.config");
+            dotnet.RestoreProjectToDirectory("myproject.csproj", "mypackages", "myconfig.config");
 
             // Verify
             var lastArgs = dotnetCliInvoker.GetLastArgs();

csharp/extractor/Semmle.Extraction.Tests/Runtime.cs

@@ -19,11 +19,7 @@ public DotNetStub(IList<string> runtimes, IList<string> sdks)
 
         public bool New(string folder) => true;
 
-        public bool RestoreProjectToDirectory(string project, string directory, out string stdout, string? pathToNugetConfig = null)
-        {
-            stdout = "";
-            return true;
-        }
+        public bool RestoreProjectToDirectory(string project, string directory, string? pathToNugetConfig = null) => true;
 
         public bool RestoreSolutionToDirectory(string solution, string directory, out IEnumerable<string> projects)
         {

csharp/extractor/Semmle.Util/Logger.cs

@@ -59,10 +59,12 @@ public sealed class FileLogger : ILogger
     {
         private readonly StreamWriter writer;
         private readonly Verbosity verbosity;
+        private readonly bool logThreadId;
 
-        public FileLogger(Verbosity verbosity, string outputFile)
+        public FileLogger(Verbosity verbosity, string outputFile, bool logThreadId)
         {
             this.verbosity = verbosity;
+            this.logThreadId = logThreadId;
 
             try
             {
@@ -93,7 +95,10 @@ private static string GetSeverityPrefix(Severity s)
         public void Log(Severity s, string text)
         {
             if (verbosity.Includes(s))
-                writer.WriteLine(GetSeverityPrefix(s) + text);
+            {
+                var threadId = this.logThreadId ? $"[{Environment.CurrentManagedThreadId:D3}] " : "";
+                writer.WriteLine(threadId + GetSeverityPrefix(s) + text);
+            }
         }
     }
 
@@ -103,10 +108,12 @@ public void Log(Severity s, string text)
     public sealed class ConsoleLogger : ILogger
     {
         private readonly Verbosity verbosity;
+        private readonly bool logThreadId;
 
-        public ConsoleLogger(Verbosity verbosity)
+        public ConsoleLogger(Verbosity verbosity, bool logThreadId)
         {
             this.verbosity = verbosity;
+            this.logThreadId = logThreadId;
         }
 
         public void Dispose() { }
@@ -136,7 +143,10 @@ private static string GetSeverityPrefix(Severity s)
         public void Log(Severity s, string text)
         {
             if (verbosity.Includes(s))
-                GetConsole(s).WriteLine(GetSeverityPrefix(s) + text);
+            {
+                var threadId = this.logThreadId ? $"[{Environment.CurrentManagedThreadId:D3}] " : "";
+                GetConsole(s).WriteLine(threadId + GetSeverityPrefix(s) + text);
+            }
         }
     }