From 13a8168c8e62b93ef284488ccc770c04d1cb6b0f Mon Sep 17 00:00:00 2001 From: Tamas Vajk Date: Wed, 24 Jan 2024 11:16:07 +0100 Subject: [PATCH] C#: Improve log messages in standalone extractor --- .../AssemblyCache.cs | 37 ++- .../AssemblyInfo.cs | 15 -- .../DependencyManager.cs | 244 +++++++++--------- .../DotNetCliInvoker.cs | 16 +- .../FileContent.cs | 3 +- .../NugetPackages.cs | 42 +-- .../ProgressMonitor.cs | 111 +------- .../Razor.cs | 14 +- .../Semmle.Extraction.Tests/LoggerStub.cs | 2 +- .../Semmle.Util.Tests/CanonicalPathCache.cs | 2 +- .../extractor/Semmle.Util.Tests/FileUtils.cs | 2 +- csharp/extractor/Semmle.Util/Logger.cs | 24 +- 12 files changed, 194 insertions(+), 318 deletions(-) diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyCache.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyCache.cs index 3a124d13e0e..270dee28d4c 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyCache.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyCache.cs @@ -21,17 +21,18 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// Callback for progress. public AssemblyCache(IEnumerable paths, IEnumerable frameworkPaths, ProgressMonitor progressMonitor) { + this.progressMonitor = progressMonitor; foreach (var path in paths) { if (File.Exists(path)) { - pendingDllsToIndex.Enqueue(path); + dllsToIndex.Add(path); continue; } if (Directory.Exists(path)) { - progressMonitor.FindingFiles(path); + progressMonitor.LogInfo($"Finding reference DLLs in {path}..."); AddReferenceDirectory(path); } else @@ -52,7 +53,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching { foreach (var dll in new DirectoryInfo(dir).EnumerateFiles("*.dll", SearchOption.AllDirectories)) { - pendingDllsToIndex.Enqueue(dll.FullName); + dllsToIndex.Add(dll.FullName); } } @@ -62,12 +63,16 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// private void IndexReferences(IEnumerable frameworkPaths) { + progressMonitor.LogInfo($"Indexing {dllsToIndex.Count} assemblies..."); + // Read all of the files - foreach (var filename in pendingDllsToIndex) + foreach (var filename in dllsToIndex) { IndexReference(filename); } + progressMonitor.LogInfo($"Read {assemblyInfoByFileName.Count} assembly infos"); + foreach (var info in assemblyInfoByFileName.Values .OrderBy(info => info.Name) .OrderAssemblyInfosByPreference(frameworkPaths)) @@ -83,25 +88,16 @@ namespace Semmle.Extraction.CSharp.DependencyFetching { try { + progressMonitor.LogDebug($"Reading assembly info from {filename}"); var info = AssemblyInfo.ReadFromFile(filename); assemblyInfoByFileName[filename] = info; } catch (AssemblyLoadException) { - failedAssemblyInfoFileNames.Add(filename); + progressMonitor.LogInfo($"Couldn't read assembly info from {filename}"); } } - /// - /// The number of DLLs which are assemblies. - /// - public int AssemblyCount => assemblyInfoByFileName.Count; - - /// - /// The number of DLLs which weren't assemblies. (E.g. C++). - /// - public int NonAssemblyCount => failedAssemblyInfoFileNames.Count; - /// /// Given an assembly id, determine its full info. /// @@ -113,8 +109,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching if (failedAssemblyInfoIds.Contains(id)) throw new AssemblyLoadException(); - string assemblyName; - (id, assemblyName) = AssemblyInfo.ComputeSanitizedAssemblyInfo(id); + (id, var assemblyName) = AssemblyInfo.ComputeSanitizedAssemblyInfo(id); // Look up the id in our references map. if (assemblyInfoById.TryGetValue(id, out var result)) @@ -164,17 +159,15 @@ namespace Semmle.Extraction.CSharp.DependencyFetching throw new AssemblyLoadException(); } - private readonly Queue pendingDllsToIndex = new Queue(); + private readonly List dllsToIndex = new List(); private readonly Dictionary assemblyInfoByFileName = new Dictionary(); - // List of DLLs which are not assemblies. - // We probably don't need to keep this - private readonly List failedAssemblyInfoFileNames = new List(); - // Map from assembly id (in various formats) to the full info. private readonly Dictionary assemblyInfoById = new Dictionary(); private readonly HashSet failedAssemblyInfoIds = new HashSet(); + + private readonly ProgressMonitor progressMonitor; } } diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyInfo.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyInfo.cs index d3522025e27..49328f6a78f 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyInfo.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/AssemblyInfo.cs @@ -120,21 +120,6 @@ namespace Semmle.Extraction.CSharp.DependencyFetching NetCoreVersion = netCoreVersion; } - /// - /// Get AssemblyInfo from a loaded Assembly. - /// - /// The assembly. - /// Info about the assembly. - public static AssemblyInfo MakeFromAssembly(Assembly assembly) - { - if (assembly.FullName is null) - { - throw new InvalidOperationException("Assembly with empty full name is not expected."); - } - - return new AssemblyInfo(assembly.FullName, assembly.Location); - } - /// /// Returns the id and name of the assembly that would be created from the received id. /// diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DependencyManager.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DependencyManager.cs index 710de21c5d0..c4a1f3a0a71 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DependencyManager.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DependencyManager.cs @@ -18,11 +18,10 @@ namespace Semmle.Extraction.CSharp.DependencyFetching { private readonly AssemblyCache assemblyCache; private readonly ProgressMonitor progressMonitor; + + // Only used as a set, but ConcurrentDictionary is the only concurrent set in .NET. private readonly IDictionary usedReferences = new ConcurrentDictionary(); - private readonly IDictionary sources = new ConcurrentDictionary(); private readonly IDictionary unresolvedReferences = new ConcurrentDictionary(); - private int failedProjects; - private int succeededProjects; private readonly List nonGeneratedSources; private readonly List generatedSources; private int conflictedReferences = 0; @@ -65,12 +64,11 @@ namespace Semmle.Extraction.CSharp.DependencyFetching } catch { - progressMonitor.MissingDotNet(); + progressMonitor.LogError("Missing dotnet CLI"); throw; } - this.progressMonitor.FindingFiles(srcDir); - + progressMonitor.LogInfo($"Finding files in {srcDir}..."); var allFiles = GetAllFiles().ToList(); var binaryFileExtensions = new HashSet(new[] { ".dll", ".exe" }); // TODO: add more binary file extensions. @@ -79,10 +77,12 @@ namespace Semmle.Extraction.CSharp.DependencyFetching this.fileContent = new FileContent(progressMonitor, smallNonBinaryFiles); this.nonGeneratedSources = allNonBinaryFiles.SelectFileNamesByExtension(".cs").ToList(); this.generatedSources = new(); - var allProjects = allNonBinaryFiles.SelectFileNamesByExtension(".csproj"); - var allSolutions = allNonBinaryFiles.SelectFileNamesByExtension(".sln"); + var allProjects = allNonBinaryFiles.SelectFileNamesByExtension(".csproj").ToList(); + var allSolutions = allNonBinaryFiles.SelectFileNamesByExtension(".sln").ToList(); var dllPaths = allFiles.SelectFileNamesByExtension(".dll").ToHashSet(); + progressMonitor.LogInfo($"Found {allFiles.Count} files, {nonGeneratedSources.Count} source files, {allProjects.Count} project files, {allSolutions.Count} solution files, {dllPaths.Count} DLLs."); + RestoreNugetPackages(allNonBinaryFiles, allProjects, allSolutions, dllPaths); // Find DLLs in the .Net / Asp.Net Framework // This needs to come after the nuget restore, because the nuget restore might fetch the .NET Core/Framework reference assemblies. @@ -102,33 +102,35 @@ namespace Semmle.Extraction.CSharp.DependencyFetching // Output the findings foreach (var r in usedReferences.Keys.OrderBy(r => r)) { - progressMonitor.ResolvedReference(r); + progressMonitor.LogInfo($"Resolved reference {r}"); } foreach (var r in unresolvedReferences.OrderBy(r => r.Key)) { - progressMonitor.UnresolvedReference(r.Key, r.Value); + progressMonitor.LogInfo($"Unresolved reference {r.Key} in project {r.Value}"); } var webViewExtractionOption = Environment.GetEnvironmentVariable("CODEQL_EXTRACTOR_CSHARP_STANDALONE_EXTRACT_WEB_VIEWS"); if (bool.TryParse(webViewExtractionOption, out var shouldExtractWebViews) && shouldExtractWebViews) { + progressMonitor.LogInfo("Generating source files from cshtml and razor files..."); GenerateSourceFilesFromWebViews(allNonBinaryFiles); } GenerateSourceFileFromImplicitUsings(); - progressMonitor.Summary( - AllSourceFiles.Count(), - ProjectSourceFiles.Count(), - MissingSourceFiles.Count(), - ReferenceFiles.Count(), - UnresolvedReferences.Count(), - conflictedReferences, - succeededProjects + failedProjects, - failedProjects, - DateTime.Now - startTime); + const int align = 6; + progressMonitor.LogInfo(""); + progressMonitor.LogInfo("Build analysis summary:"); + progressMonitor.LogInfo($"{this.nonGeneratedSources.Count,align} source files in the filesystem"); + progressMonitor.LogInfo($"{this.generatedSources.Count,align} generated source files"); + progressMonitor.LogInfo($"{allSolutions.Count,align} solution files"); + progressMonitor.LogInfo($"{allProjects.Count,align} project files in the filesystem"); + progressMonitor.LogInfo($"{usedReferences.Keys.Count,align} resolved references"); + progressMonitor.LogInfo($"{unresolvedReferences.Count,align} unresolved references"); + progressMonitor.LogInfo($"{conflictedReferences,align} resolved assembly conflicts"); + progressMonitor.LogInfo($"Build analysis completed in {DateTime.Now - startTime}"); } private HashSet AddFrameworkDlls(HashSet dllPaths) @@ -152,7 +154,17 @@ namespace Semmle.Extraction.CSharp.DependencyFetching var nugetPackageDlls = legacyPackageDirectory.DirInfo.GetFiles("*.dll", new EnumerationOptions { RecurseSubdirectories = true }); var nugetPackageDllPaths = nugetPackageDlls.Select(f => f.FullName).ToHashSet(); var excludedPaths = nugetPackageDllPaths - .Where(path => IsPathInSubfolder(path, legacyPackageDirectory.DirInfo.FullName, "tools")); + .Where(path => IsPathInSubfolder(path, legacyPackageDirectory.DirInfo.FullName, "tools")) + .ToList(); + + if (nugetPackageDllPaths.Count > 0) + { + progressMonitor.LogInfo($"Restored {nugetPackageDllPaths.Count} Nuget DLLs."); + } + if (excludedPaths.Count > 0) + { + progressMonitor.LogInfo($"Excluding {excludedPaths.Count} Nuget DLLs."); + } foreach (var excludedPath in excludedPaths) { @@ -162,9 +174,9 @@ namespace Semmle.Extraction.CSharp.DependencyFetching nugetPackageDllPaths.ExceptWith(excludedPaths); dllPaths.UnionWith(nugetPackageDllPaths); } - catch (FileNotFoundException) + catch (Exception) { - progressMonitor.MissingNuGet(); + progressMonitor.LogError("Failed to restore Nuget packages with nuget.exe"); } var restoredProjects = RestoreSolutions(allSolutions, out var assets1); @@ -220,7 +232,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching if (isInAnalyzersFolder) { usedReferences.Remove(filename); - progressMonitor.RemovedReference(filename); + progressMonitor.LogInfo($"Removed analyzer reference {filename}"); } } } @@ -248,7 +260,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching dllPaths.Add(selectedFrameworkFolder); frameworkLocations.Add(selectedFrameworkFolder); - progressMonitor.LogInfo($"Found {frameworkType} DLLs in NuGet packages at {selectedFrameworkFolder}. Not adding installation directory."); + progressMonitor.LogInfo($"Found {frameworkType} DLLs in NuGet packages at {selectedFrameworkFolder}."); } private void AddNetFrameworkDlls(ISet dllPaths, ISet frameworkLocations) @@ -300,11 +312,11 @@ namespace Semmle.Extraction.CSharp.DependencyFetching } var packagePathPrefix = Path.Combine(packageFolder, packagePrefix.ToLowerInvariant()); - var toRemove = dllPaths.Where(s => s.ToLowerInvariant().StartsWith(packagePathPrefix)); + var toRemove = dllPaths.Where(s => s.StartsWith(packagePathPrefix, StringComparison.InvariantCultureIgnoreCase)); foreach (var path in toRemove) { dllPaths.Remove(path); - progressMonitor.RemovedReference(path); + progressMonitor.LogInfo($"Removed reference {path}"); } } @@ -346,18 +358,26 @@ namespace Semmle.Extraction.CSharp.DependencyFetching .FullName; } - private IEnumerable GetAllPackageDirectories() + private ICollection GetAllPackageDirectories() { return new DirectoryInfo(packageDirectory.DirInfo.FullName) .EnumerateDirectories("*", new EnumerationOptions { MatchCasing = MatchCasing.CaseInsensitive, RecurseSubdirectories = false }) - .Select(d => d.Name); + .Select(d => d.Name) + .ToList(); } - private void LogAllUnusedPackages(DependencyContainer dependencies) => - GetAllPackageDirectories() + private void LogAllUnusedPackages(DependencyContainer dependencies) + { + var allPackageDirectories = GetAllPackageDirectories(); + + progressMonitor.LogInfo($"Restored {allPackageDirectories.Count} packages"); + progressMonitor.LogInfo($"Found {dependencies.Packages.Count} packages in project.asset.json files"); + + allPackageDirectories .Where(package => !dependencies.Packages.Contains(package)) .Order() .ForEach(package => progressMonitor.LogInfo($"Unused package: {package}")); + } private void GenerateSourceFileFromImplicitUsings() { @@ -380,6 +400,8 @@ namespace Semmle.Extraction.CSharp.DependencyFetching usings.UnionWith(fileContent.CustomImplicitUsings); + progressMonitor.LogInfo($"Generating source file for implicit usings. Namespaces: {string.Join(", ", usings.OrderBy(u => u))}"); + if (usings.Count > 0) { var tempDir = GetTemporaryWorkingDirectory("implicitUsings"); @@ -401,29 +423,28 @@ namespace Semmle.Extraction.CSharp.DependencyFetching private void GenerateSourceFilesFromWebViews(List allFiles) { - progressMonitor.LogInfo($"Generating source files from cshtml and razor files."); - var views = allFiles.SelectFileNamesByExtension(".cshtml", ".razor").ToArray(); - - if (views.Length > 0) + if (views.Length == 0) { - progressMonitor.LogInfo($"Found {views.Length} cshtml and razor files."); + return; + } - var sdk = new Sdk(dotnet).GetNewestSdk(); - if (sdk != null) + progressMonitor.LogInfo($"Found {views.Length} cshtml and razor files."); + + var sdk = new Sdk(dotnet).GetNewestSdk(); + if (sdk != null) + { + try { - try - { - var razor = new Razor(sdk, dotnet, progressMonitor); - var targetDir = GetTemporaryWorkingDirectory("razor"); - var generatedFiles = razor.GenerateFiles(views, usedReferences.Keys, targetDir); - this.generatedSources.AddRange(generatedFiles); - } - catch (Exception ex) - { - // It's okay, we tried our best to generate source files from cshtml files. - progressMonitor.LogInfo($"Failed to generate source files from cshtml files: {ex.Message}"); - } + var razor = new Razor(sdk, dotnet, progressMonitor); + var targetDir = GetTemporaryWorkingDirectory("razor"); + var generatedFiles = razor.GenerateFiles(views, usedReferences.Keys, targetDir); + this.generatedSources.AddRange(generatedFiles); + } + catch (Exception ex) + { + // It's okay, we tried our best to generate source files from cshtml files. + progressMonitor.LogInfo($"Failed to generate source files from cshtml files: {ex.Message}"); } } } @@ -499,7 +520,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// private void ResolveConflicts(IEnumerable frameworkPaths) { - var sortedReferences = new List(); + var sortedReferences = new List(usedReferences.Count); foreach (var usedReference in usedReferences) { try @@ -509,7 +530,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching } catch (AssemblyLoadException) { - progressMonitor.Log(Util.Logging.Severity.Warning, $"Could not load assembly information from {usedReference.Key}"); + progressMonitor.Log(Severity.Warning, $"Could not load assembly information from {usedReference.Key}"); } } @@ -517,6 +538,8 @@ namespace Semmle.Extraction.CSharp.DependencyFetching .OrderAssemblyInfosByPreference(frameworkPaths) .ToList(); + progressMonitor.LogInfo($"Reference list contains {sortedReferences.Count} assemblies"); + var finalAssemblyList = new Dictionary(); // Pick the highest version for each assembly name @@ -532,15 +555,23 @@ namespace Semmle.Extraction.CSharp.DependencyFetching UseReference(r); } + progressMonitor.LogInfo($"After conflict resolution, reference list contains {finalAssemblyList.Count} assemblies"); + // Report the results foreach (var r in sortedReferences) { var resolvedInfo = finalAssemblyList[r.Name]; if (resolvedInfo.Version != r.Version || resolvedInfo.NetCoreVersion != r.NetCoreVersion) { - progressMonitor.ResolvedConflict(r.Id, resolvedInfo.Id + resolvedInfo.NetCoreVersion is null ? "" : $" (.NET Core {resolvedInfo.NetCoreVersion})"); + var asm = resolvedInfo.Id + (resolvedInfo.NetCoreVersion is null ? "" : $" (.NET Core {resolvedInfo.NetCoreVersion})"); + progressMonitor.LogInfo($"Resolved {r.Id} as {asm}"); ++conflictedReferences; } + + if (r != resolvedInfo) + { + progressMonitor.LogDebug($"Resolved {r.Id} as {resolvedInfo.Id} from {resolvedInfo.Filename}"); + } } } @@ -550,22 +581,11 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// The filename of the reference. private void UseReference(string reference) => usedReferences[reference] = true; - /// - /// Store that a particular source file is used (by a project file). - /// - /// The source file. - private void UseSource(FileInfo sourceFile) => sources[sourceFile.FullName] = sourceFile.Exists; - /// /// The list of resolved reference files. /// public IEnumerable ReferenceFiles => usedReferences.Keys; - /// - /// The list of source files used in projects. - /// - public IEnumerable ProjectSourceFiles => sources.Where(s => s.Value).Select(s => s.Key); - /// /// All of the generated source files in the source directory. /// @@ -581,12 +601,6 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// public IEnumerable UnresolvedReferences => unresolvedReferences.Select(r => r.Key); - /// - /// List of source files which were mentioned in project files but - /// do not exist on the file system. - /// - public IEnumerable MissingSourceFiles => sources.Where(s => !s.Value).Select(s => s.Key); - /// /// Record that a particular reference couldn't be resolved. /// Note that this records at most one project file per missing reference. @@ -595,23 +609,31 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// The project file making the reference. private void UnresolvedReference(string id, string projectFile) => unresolvedReferences[id] = projectFile; - /// - /// Reads all the source files and references from the given list of projects. - /// - /// The list of projects to analyse. - private void AnalyseProjectFiles(IEnumerable projectFiles) + private void AnalyseSolutions(IEnumerable solutions) { - foreach (var proj in projectFiles) + Parallel.ForEach(solutions, new ParallelOptions { MaxDegreeOfParallelism = options.Threads }, solutionFile => { - AnalyseProject(proj); - } + try + { + var sln = new SolutionFile(solutionFile); + progressMonitor.LogInfo($"Analyzing {solutionFile}..."); + foreach (var proj in sln.Projects.Select(p => new FileInfo(p))) + { + AnalyseProject(proj); + } + } + catch (Microsoft.Build.Exceptions.InvalidProjectFileException ex) + { + progressMonitor.LogInfo($"Couldn't read solution file {solutionFile}: {ex.BaseMessage}"); + } + }); } private void AnalyseProject(FileInfo project) { if (!project.Exists) { - progressMonitor.MissingProject(project.FullName); + progressMonitor.LogInfo($"Couldn't read project file {project.FullName}"); return; } @@ -631,23 +653,11 @@ namespace Semmle.Extraction.CSharp.DependencyFetching UnresolvedReference(@ref, project.FullName); } } - - foreach (var src in csProj.Sources) - { - // Make a note of which source files the projects use. - // This information doesn't affect the build but is dumped - // as diagnostic output. - UseSource(new FileInfo(src)); - } - - ++succeededProjects; } catch (Exception ex) // lgtm[cs/catch-of-all-exceptions] { - ++failedProjects; - progressMonitor.FailedProjectFile(project.FullName, ex.Message); + progressMonitor.LogInfo($"Couldn't read project file {project.FullName}: {ex.Message}"); } - } /// @@ -664,7 +674,8 @@ namespace Semmle.Extraction.CSharp.DependencyFetching var assetFiles = new List(); var projects = solutions.SelectMany(solution => { - dotnet.RestoreSolutionToDirectory(solution, packageDirectory.DirInfo.FullName, forceDotnetRefAssemblyFetching: true, out var restoredProjects, out var a); + progressMonitor.LogInfo($"Restoring solution {solution}..."); + var success = dotnet.RestoreSolutionToDirectory(solution, packageDirectory.DirInfo.FullName, forceDotnetRefAssemblyFetching: true, out var restoredProjects, out var a); assetFiles.AddRange(a); return restoredProjects; }); @@ -683,7 +694,8 @@ namespace Semmle.Extraction.CSharp.DependencyFetching var assetFiles = new List(); Parallel.ForEach(projects, new ParallelOptions { MaxDegreeOfParallelism = options.Threads }, project => { - dotnet.RestoreProjectToDirectory(project, packageDirectory.DirInfo.FullName, forceDotnetRefAssemblyFetching: true, out var a, out var _); + progressMonitor.LogInfo($"Restoring project {project}..."); + var success = dotnet.RestoreProjectToDirectory(project, packageDirectory.DirInfo.FullName, forceDotnetRefAssemblyFetching: true, out var a, out var _); assetFiles.AddRange(a); }); assets = assetFiles; @@ -691,18 +703,30 @@ namespace Semmle.Extraction.CSharp.DependencyFetching private void DownloadMissingPackages(List allFiles, ISet dllPaths) { + var alreadyDownloadedPackages = Directory.GetDirectories(packageDirectory.DirInfo.FullName) + .Select(d => Path.GetFileName(d).ToLowerInvariant()); + var notYetDownloadedPackages = fileContent.AllPackages + .Except(alreadyDownloadedPackages) + .ToList(); + if (notYetDownloadedPackages.Count == 0) + { + return; + } + + progressMonitor.LogInfo($"Found {notYetDownloadedPackages.Count} packages that are not yet restored"); + var nugetConfigs = allFiles.SelectFileNamesByName("nuget.config").ToArray(); string? nugetConfig = null; if (nugetConfigs.Length > 1) { - progressMonitor.MultipleNugetConfig(nugetConfigs); + progressMonitor.LogInfo($"Found multiple nuget.config files: {string.Join(", ", nugetConfigs)}."); nugetConfig = allFiles .SelectRootFiles(sourceDir) .SelectFileNamesByName("nuget.config") .FirstOrDefault(); if (nugetConfig == null) { - progressMonitor.NoTopLevelNugetConfig(); + progressMonitor.LogInfo("Could not find a top-level nuget.config file."); } } else @@ -710,13 +734,14 @@ namespace Semmle.Extraction.CSharp.DependencyFetching nugetConfig = nugetConfigs.FirstOrDefault(); } - var alreadyDownloadedPackages = Directory.GetDirectories(packageDirectory.DirInfo.FullName) - .Select(d => Path.GetFileName(d).ToLowerInvariant()); - var notYetDownloadedPackages = fileContent.AllPackages.Except(alreadyDownloadedPackages); + if (nugetConfig != null) + { + progressMonitor.LogInfo($"Using nuget.config file {nugetConfig}."); + } Parallel.ForEach(notYetDownloadedPackages, new ParallelOptions { MaxDegreeOfParallelism = options.Threads }, package => { - progressMonitor.NugetInstall(package); + progressMonitor.LogInfo($"Restoring package {package}..."); using var tempDir = new TemporaryDirectory(ComputeTempDirectory(package, "missingpackages_workingdir")); var success = dotnet.New(tempDir.DirInfo.FullName); if (!success) @@ -743,7 +768,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching if (!success) { - progressMonitor.FailedToRestoreNugetPackage(package); + progressMonitor.LogInfo($"Failed to restore nuget package {package}"); } } }); @@ -751,23 +776,6 @@ namespace Semmle.Extraction.CSharp.DependencyFetching dllPaths.Add(missingPackageDirectory.DirInfo.FullName); } - private void AnalyseSolutions(IEnumerable solutions) - { - Parallel.ForEach(solutions, new ParallelOptions { MaxDegreeOfParallelism = options.Threads }, solutionFile => - { - try - { - var sln = new SolutionFile(solutionFile); - progressMonitor.AnalysingSolution(solutionFile); - AnalyseProjectFiles(sln.Projects.Select(p => new FileInfo(p)).Where(p => p.Exists)); - } - catch (Microsoft.Build.Exceptions.InvalidProjectFileException ex) - { - progressMonitor.FailedProjectFile(solutionFile, ex.BaseMessage); - } - }); - } - public void Dispose(TemporaryDirectory? dir, string name) { try diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DotNetCliInvoker.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DotNetCliInvoker.cs index 5e7c2b60803..db338e3c9e5 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DotNetCliInvoker.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/DotNetCliInvoker.cs @@ -35,21 +35,15 @@ namespace Semmle.Extraction.CSharp.DependencyFetching private bool RunCommandAux(string args, out IList output) { - progressMonitor.RunningProcess($"{Exec} {args}"); + progressMonitor.LogInfo($"Running {Exec} {args}"); 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 threadId = Environment.CurrentManagedThreadId; + void onOut(string s) => progressMonitor.LogInfo(s, threadId); + void onError(string s) => progressMonitor.LogError(s, threadId); var exitCode = pi.ReadOutput(out output, onOut, onError); if (exitCode != 0) { - progressMonitor.CommandFailed(Exec, args, exitCode); + progressMonitor.LogError($"Command {Exec} {args} failed with exit code {exitCode}"); return false; } return true; diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/FileContent.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/FileContent.cs index 578ae81ebe2..04961c06143 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/FileContent.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/FileContent.cs @@ -192,7 +192,8 @@ namespace Semmle.Extraction.CSharp.DependencyFetching } catch (Exception ex) { - progressMonitor.FailedToReadFile(file, ex); + progressMonitor.LogInfo($"Failed to read file {file}"); + progressMonitor.LogDebug($"Failed to read file {file}, exception: {ex}"); } } } diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/NugetPackages.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/NugetPackages.cs index 541853faf38..b0f4803ddce 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/NugetPackages.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/NugetPackages.cs @@ -42,6 +42,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching if (packageFiles.Length > 0) { + progressMonitor.LogInfo($"Found {packageFiles.Length} packages.config files, trying to use nuget.exe for package restore"); nugetExe = ResolveNugetExe(sourceDir); } else @@ -65,14 +66,11 @@ namespace Semmle.Extraction.CSharp.DependencyFetching var nuget = Path.Combine(directory, "nuget", "nuget.exe"); if (File.Exists(nuget)) { - progressMonitor.FoundNuGet(nuget); + progressMonitor.LogInfo($"Found nuget.exe at {nuget}"); return nuget; } - else - { - progressMonitor.LogInfo($"Nuget.exe could not be found at {nuget}"); - return DownloadNugetExe(sourceDir); - } + + return DownloadNugetExe(sourceDir); } private string DownloadNugetExe(string sourceDir) @@ -83,7 +81,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching // Nuget.exe already exists in the .nuget directory. if (File.Exists(nuget)) { - progressMonitor.FoundNuGet(nuget); + progressMonitor.LogInfo($"Found nuget.exe at {nuget}"); return nuget; } @@ -108,7 +106,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching /// The package file. private void RestoreNugetPackage(string package) { - progressMonitor.NugetInstall(package); + progressMonitor.LogInfo($"Restoring file {package}..."); /* Use nuget.exe to install a package. * Note that there is a clutch of NuGet assemblies which could be used to @@ -135,29 +133,17 @@ namespace Semmle.Extraction.CSharp.DependencyFetching UseShellExecute = false }; - try + var threadId = Environment.CurrentManagedThreadId; + void onOut(string s) => progressMonitor.LogInfo(s, threadId); + void onError(string s) => progressMonitor.LogError(s, threadId); + var exitCode = pi.ReadOutput(out var _, onOut, onError); + if (exitCode != 0) { - using var p = Process.Start(pi); - - if (p is null) - { - progressMonitor.FailedNugetCommand(pi.FileName, pi.Arguments, "Couldn't start process."); - return; - } - - var output = p.StandardOutput.ReadToEnd(); - var error = p.StandardError.ReadToEnd(); - - p.WaitForExit(); - if (p.ExitCode != 0) - { - progressMonitor.FailedNugetCommand(pi.FileName, pi.Arguments, output + error); - } + progressMonitor.LogError($"Command {pi.FileName} {pi.Arguments} failed with exit code {exitCode}"); } - catch (Exception ex) - when (ex is System.ComponentModel.Win32Exception || ex is FileNotFoundException) + else { - progressMonitor.FailedNugetCommand(pi.FileName, pi.Arguments, ex.Message); + progressMonitor.LogInfo($"Restored file {package}"); } } diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/ProgressMonitor.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/ProgressMonitor.cs index 7505c9a2785..b034c5b1240 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/ProgressMonitor.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/ProgressMonitor.cs @@ -1,5 +1,4 @@ -using System; -using Semmle.Util.Logging; +using Semmle.Util.Logging; namespace Semmle.Extraction.CSharp.DependencyFetching { @@ -15,113 +14,13 @@ namespace Semmle.Extraction.CSharp.DependencyFetching public void Log(Severity severity, string message) => logger.Log(severity, message); - public void LogInfo(string message) => - logger.Log(Severity.Info, message); + public void LogInfo(string message, int? threadId = null) => + logger.Log(Severity.Info, message, threadId); public void LogDebug(string message) => logger.Log(Severity.Debug, message); - private void LogError(string message) => - logger.Log(Severity.Error, message); - - public void FindingFiles(string dir) => - LogInfo($"Finding files in {dir}..."); - - public void IndexingReferences(int count) - { - LogInfo("Indexing..."); - LogDebug($"Indexing {count} DLLs..."); - } - - public void UnresolvedReference(string id, string project) - { - LogInfo($"Unresolved reference {id}"); - LogDebug($"Unresolved {id} referenced by {project}"); - } - - public void AnalysingSolution(string filename) => - LogInfo($"Analyzing {filename}..."); - - public void FailedProjectFile(string filename, string reason) => - LogInfo($"Couldn't read project file {filename}: {reason}"); - - public void FailedNugetCommand(string exe, string args, string message) - { - LogInfo($"Command failed: {exe} {args}"); - LogInfo($" {message}"); - } - - public void NugetInstall(string package) => - LogInfo($"Restoring {package}..."); - - public void ResolvedReference(string filename) => - LogInfo($"Resolved reference {filename}"); - - public void RemovedReference(string filename) => - LogInfo($"Removed reference {filename}"); - - public void Summary(int existingSources, int usedSources, int missingSources, - int references, int unresolvedReferences, - int resolvedConflicts, int totalProjects, int failedProjects, - TimeSpan analysisTime) - { - const int align = 6; - LogInfo(""); - LogInfo("Build analysis summary:"); - LogInfo($"{existingSources,align} source files in the filesystem"); - LogInfo($"{usedSources,align} source files in project files"); - LogInfo($"{missingSources,align} sources missing from project files"); - LogInfo($"{references,align} resolved references"); - LogInfo($"{unresolvedReferences,align} unresolved references"); - LogInfo($"{resolvedConflicts,align} resolved assembly conflicts"); - LogInfo($"{totalProjects,align} projects"); - LogInfo($"{failedProjects,align} missing/failed projects"); - LogInfo($"Build analysis completed in {analysisTime}"); - } - - public void ResolvedConflict(string asm1, string asm2) => - LogDebug($"Resolved {asm1} as {asm2}"); - - public void MissingProject(string projectFile) => - LogInfo($"Solution is missing {projectFile}"); - - public void CommandFailed(string exe, string arguments, int exitCode) => - LogError($"Command {exe} {arguments} failed with exit code {exitCode}"); - - public void MissingNuGet() => - LogError("Missing nuget.exe"); - - public void FoundNuGet(string path) => - LogInfo($"Found nuget.exe at {path}"); - - public void MissingDotNet() => - LogError("Missing dotnet CLI"); - - public void RunningProcess(string command) => - LogInfo($"Running {command}"); - - public void FailedToRestoreNugetPackage(string package) => - LogInfo($"Failed to restore nuget package {package}"); - - public void FailedToReadFile(string file, Exception ex) - { - LogInfo($"Failed to read file {file}"); - LogDebug($"Failed to read file {file}, exception: {ex}"); - } - - public void MultipleNugetConfig(string[] nugetConfigs) => - LogInfo($"Found multiple nuget.config files: {string.Join(", ", nugetConfigs)}."); - - internal void NoTopLevelNugetConfig() => - LogInfo("Could not find a top-level nuget.config file."); - - internal void RazorSourceGeneratorMissing(string fullPath) => - LogInfo($"Razor source generator folder {fullPath} does not exist."); - - internal void CscMissing(string cscPath) => - LogInfo($"Csc.exe not found at {cscPath}."); - - internal void RazorCscArgs(string args) => - LogInfo($"Running CSC to generate Razor source files. Args: {args}."); + public void LogError(string message, int? threadId = null) => + logger.Log(Severity.Error, message, threadId); } } diff --git a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/Razor.cs b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/Razor.cs index 9d910835f90..be9274982ed 100644 --- a/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/Razor.cs +++ b/csharp/extractor/Semmle.Extraction.CSharp.DependencyFetching/Razor.cs @@ -22,16 +22,18 @@ namespace Semmle.Extraction.CSharp.DependencyFetching this.dotNet = dotNet; sourceGeneratorFolder = Path.Combine(this.sdk.FullPath, "Sdks", "Microsoft.NET.Sdk.Razor", "source-generators"); + this.progressMonitor.LogInfo($"Razor source generator folder: {sourceGeneratorFolder}"); if (!Directory.Exists(sourceGeneratorFolder)) { - this.progressMonitor.RazorSourceGeneratorMissing(sourceGeneratorFolder); + this.progressMonitor.LogInfo($"Razor source generator folder {sourceGeneratorFolder} does not exist."); throw new Exception($"Razor source generator folder {sourceGeneratorFolder} does not exist."); } cscPath = Path.Combine(this.sdk.FullPath, "Roslyn", "bincore", "csc.dll"); + this.progressMonitor.LogInfo($"Razor source generator CSC: {cscPath}"); if (!File.Exists(cscPath)) { - this.progressMonitor.CscMissing(cscPath); + this.progressMonitor.LogInfo($"Csc.exe not found at {cscPath}."); throw new Exception($"csc.dll {cscPath} does not exist."); } } @@ -85,7 +87,7 @@ namespace Semmle.Extraction.CSharp.DependencyFetching var argsString = args.ToString(); - progressMonitor.RazorCscArgs(argsString); + progressMonitor.LogInfo($"Running CSC to generate Razor source files with arguments: {argsString}."); using (var sw = new StreamWriter(cscArgsPath)) { @@ -94,7 +96,11 @@ namespace Semmle.Extraction.CSharp.DependencyFetching dotNet.Exec($"\"{cscPath}\" /noconfig @\"{cscArgsPath}\""); - return Directory.GetFiles(outputFolder, "*.*", new EnumerationOptions { RecurseSubdirectories = true }); + var files = Directory.GetFiles(outputFolder, "*.*", new EnumerationOptions { RecurseSubdirectories = true }); + + progressMonitor.LogInfo($"Generated {files.Length} source files from cshtml files."); + + return files; } finally { diff --git a/csharp/extractor/Semmle.Extraction.Tests/LoggerStub.cs b/csharp/extractor/Semmle.Extraction.Tests/LoggerStub.cs index 78e85b8d60f..9120de8be45 100644 --- a/csharp/extractor/Semmle.Extraction.Tests/LoggerStub.cs +++ b/csharp/extractor/Semmle.Extraction.Tests/LoggerStub.cs @@ -4,7 +4,7 @@ namespace Semmle.Extraction.Tests { internal class LoggerStub : ILogger { - public void Log(Severity severity, string message) { } + public void Log(Severity severity, string message, int? threadId = null) { } public void Dispose() { } } diff --git a/csharp/extractor/Semmle.Util.Tests/CanonicalPathCache.cs b/csharp/extractor/Semmle.Util.Tests/CanonicalPathCache.cs index 1a50fd87679..313b949810d 100644 --- a/csharp/extractor/Semmle.Util.Tests/CanonicalPathCache.cs +++ b/csharp/extractor/Semmle.Util.Tests/CanonicalPathCache.cs @@ -176,7 +176,7 @@ namespace SemmleTests.Semmle.Util { public void Dispose() { } - public void Log(Severity s, string text) { } + public void Log(Severity s, string text, int? threadId = null) { } } } } diff --git a/csharp/extractor/Semmle.Util.Tests/FileUtils.cs b/csharp/extractor/Semmle.Util.Tests/FileUtils.cs index cbc82d4b814..c0e5e91db78 100644 --- a/csharp/extractor/Semmle.Util.Tests/FileUtils.cs +++ b/csharp/extractor/Semmle.Util.Tests/FileUtils.cs @@ -57,7 +57,7 @@ namespace SemmleTests.Semmle.Util { public void Dispose() { } - public void Log(Severity s, string text) { } + public void Log(Severity s, string text, int? threadId = null) { } } } } diff --git a/csharp/extractor/Semmle.Util/Logger.cs b/csharp/extractor/Semmle.Util/Logger.cs index 747d43368b8..5194feb3937 100644 --- a/csharp/extractor/Semmle.Util/Logger.cs +++ b/csharp/extractor/Semmle.Util/Logger.cs @@ -37,7 +37,7 @@ namespace Semmle.Util.Logging /// /// Log the given text with the given severity. /// - void Log(Severity s, string text); + void Log(Severity s, string text, int? threadId = null); } public static class LoggerExtensions @@ -92,12 +92,14 @@ namespace Semmle.Util.Logging return "[" + s.ToString().ToUpper() + "] "; } - public void Log(Severity s, string text) + public void Log(Severity s, string text, int? threadId = null) { if (verbosity.Includes(s)) { - var threadId = this.logThreadId ? $"[{Environment.CurrentManagedThreadId:D3}] " : ""; - writer.WriteLine(threadId + GetSeverityPrefix(s) + text); + threadId ??= Environment.CurrentManagedThreadId; + + var prefix = this.logThreadId ? $"[{threadId:D3}] " : ""; + writer.WriteLine(prefix + GetSeverityPrefix(s) + text); } } } @@ -140,12 +142,14 @@ namespace Semmle.Util.Logging } } - public void Log(Severity s, string text) + public void Log(Severity s, string text, int? threadId = null) { if (verbosity.Includes(s)) { - var threadId = this.logThreadId ? $"[{Environment.CurrentManagedThreadId:D3}] " : ""; - GetConsole(s).WriteLine(threadId + GetSeverityPrefix(s) + text); + threadId ??= Environment.CurrentManagedThreadId; + + var prefix = this.logThreadId ? $"[{threadId:D3}] " : ""; + GetConsole(s).WriteLine(prefix + GetSeverityPrefix(s) + text); } } } @@ -170,10 +174,10 @@ namespace Semmle.Util.Logging logger2.Dispose(); } - public void Log(Severity s, string text) + public void Log(Severity s, string text, int? threadId = null) { - logger1.Log(s, text); - logger2.Log(s, text); + logger1.Log(s, text, threadId); + logger2.Log(s, text, threadId); } }