Improve CLI logging (#1242)

dotnet · Nov 10, 2023 · 7bad9e4 · 7bad9e4
1 parent 3793592
commit 7bad9e4
Show file tree

Hide file tree

Showing 16 changed files with 61 additions and 83 deletions.
diff --git a/src/CommandLine/Commands/AnalyzeCommand.cs b/src/CommandLine/Commands/AnalyzeCommand.cs
@@ -54,7 +54,7 @@ public override async Task<AnalyzeCommandResult> ExecuteAsync(ProjectOrSolution
                 || analyzerAssembly.HasAnalyzers
                 || analyzerAssembly.HasFixers)
             {
-                WriteLine($"Add analyzer assembly '{analyzerAssembly.FullName}'", ConsoleColors.DarkGray, Verbosity.Detailed);
+                WriteLine($"Loaded analyzer assembly '{analyzerAssembly.FullName}'", ConsoleColors.DarkGray, Verbosity.Detailed);
             }
         };
 
@@ -127,9 +127,4 @@ private static void WriteAnalysisResults(IEnumerable<ProjectAnalysisResult> resu
         WriteLine(Verbosity.Minimal);
         WriteLine($"{totalCount} {((totalCount == 1) ? "diagnostic" : "diagnostics")} found", ConsoleColors.Green, Verbosity.Minimal);
     }
-
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Analysis was canceled.", Verbosity.Quiet);
-    }
 }
diff --git a/src/CommandLine/Commands/FindSymbolsCommand.cs b/src/CommandLine/Commands/FindSymbolsCommand.cs
@@ -118,7 +118,7 @@ public override async Task<CommandResult> ExecuteAsync(ProjectOrSolution project
 
             allSymbols = symbols?.ToImmutableArray() ?? ImmutableArray<ISymbol>.Empty;
 
-            WriteLine($"Done analyzing solution '{solution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+            LogHelpers.WriteElapsedTime($"Analyzed solution '{solution.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
         }
 
         if (allSymbols.Any())
@@ -175,11 +175,6 @@ public override async Task<CommandResult> ExecuteAsync(ProjectOrSolution project
         return SymbolFinder.FindSymbolsAsync(project, options, progress, cancellationToken);
     }
 
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Analysis was canceled.", Verbosity.Quiet);
-    }
-
     private static void WriteSymbol(
         ISymbol symbol,
         Verbosity verbosity,

diff --git a/src/CommandLine/Commands/FixCommand.cs b/src/CommandLine/Commands/FixCommand.cs
@@ -93,15 +93,15 @@ public override async Task<FixCommandResult> ExecuteAsync(ProjectOrSolution proj
 
             CodeFixer codeFixer = GetCodeFixer(solution);
 
-            WriteLine($"Fix '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
+            WriteLine($"Analyze '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
 
             Stopwatch stopwatch = Stopwatch.StartNew();
 
             ProjectFixResult result = await codeFixer.FixProjectAsync(project, cancellationToken);
 
             stopwatch.Stop();
 
-            WriteLine($"Done fixing project '{project.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+            LogHelpers.WriteElapsedTime($"Analyzed project '{project.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
 
             results = ImmutableArray.Create(result);
         }
@@ -132,7 +132,7 @@ CodeFixer GetCodeFixer(Solution solution)
                     || analyzerAssembly.HasAnalyzers
                     || analyzerAssembly.HasFixers)
                 {
-                    WriteLine($"Add analyzer assembly '{analyzerAssembly.FullName}'", ConsoleColors.DarkGray, Verbosity.Detailed);
+                    WriteLine($"Loaded analyzer assembly '{analyzerAssembly.FullName}'", ConsoleColors.DarkGray, Verbosity.Detailed);
                 }
             };
 
@@ -284,9 +284,4 @@ protected override void ProcessResults(IList<FixCommandResult> results)
             }
         }
     }
-
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Fixing was canceled.", Verbosity.Quiet);
-    }
 }
diff --git a/src/CommandLine/Commands/FormatCommand.cs b/src/CommandLine/Commands/FormatCommand.cs
@@ -79,7 +79,7 @@ private async Task<ImmutableArray<DocumentId>> FormatSolutionAsync(Solution solu
                     LogHelpers.WriteFormattedDocuments(formattedDocuments, project, solutionDirectory);
                 }
 
-                WriteLine($"  Done analyzing '{project.Name}'", Verbosity.Normal);
+                WriteLine($"  Analyzed '{project.Name}'", Verbosity.Normal);
             });
 #else
         await Parallel.ForEachAsync(
@@ -101,7 +101,7 @@ private async Task<ImmutableArray<DocumentId>> FormatSolutionAsync(Solution solu
                     LogHelpers.WriteFormattedDocuments(formattedDocuments, project, solutionDirectory);
                 }
 
-                WriteLine($"  Done analyzing '{project.Name}'", Verbosity.Normal);
+                WriteLine($"  Analyzed '{project.Name}'", Verbosity.Normal);
             });
 #endif
 
@@ -116,7 +116,7 @@ private async Task<ImmutableArray<DocumentId>> FormatSolutionAsync(Solution solu
                 newSolution = newSolution.WithDocumentText(documentId, sourceText);
             }
 
-            WriteLine($"Apply changes to solution '{solution.FilePath}'", Verbosity.Normal);
+            WriteLine($"Applying changes to solution '{solution.FilePath}'...", Verbosity.Normal);
 
             if (!solution.Workspace.TryApplyChanges(newSolution))
             {
@@ -131,7 +131,7 @@ private async Task<ImmutableArray<DocumentId>> FormatSolutionAsync(Solution solu
         WriteLine($"{count} {((count == 1) ? "document" : "documents")} formatted", ConsoleColors.Green, Verbosity.Minimal);
 
         WriteLine(Verbosity.Minimal);
-        WriteLine($"Done formatting solution '{solution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+        LogHelpers.WriteElapsedTime($"Analyzed solution '{solution.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
 
         return changedDocuments.SelectMany(f => f).ToImmutableArray();
     }
@@ -156,7 +156,7 @@ private static async Task<ImmutableArray<DocumentId>> FormatProjectAsync(Project
         {
             Solution newSolution = newProject.Solution;
 
-            WriteLine($"Apply changes to solution '{newSolution.FilePath}'", Verbosity.Normal);
+            WriteLine($"Applying changes to solution '{newSolution.FilePath}'...", Verbosity.Normal);
 
             if (!solution.Workspace.TryApplyChanges(newSolution))
             {
@@ -183,9 +183,4 @@ private static void WriteSummary(int count)
         WriteLine(Verbosity.Minimal);
         WriteLine($"{count} {((count == 1) ? "document" : "documents")} formatted", ConsoleColors.Green, Verbosity.Minimal);
     }
-
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Formatting was canceled.", Verbosity.Minimal);
-    }
 }
diff --git a/src/CommandLine/Commands/LogicalLinesOfCodeCommand.cs b/src/CommandLine/Commands/LogicalLinesOfCodeCommand.cs
@@ -57,7 +57,7 @@ public override async Task<LinesOfCodeCommandResult> ExecuteAsync(ProjectOrSolut
 
     private async Task<CodeMetricsInfo> CountLinesAsync(Project project, ICodeMetricsService service, CodeMetricsOptions options, CancellationToken cancellationToken)
     {
-        WriteLine($"Count logical lines for '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
+        WriteLine($"Counting logical lines for '{project.Name}'...", ConsoleColors.Cyan, Verbosity.Minimal);
 
         Stopwatch stopwatch = Stopwatch.StartNew();
 
@@ -78,14 +78,14 @@ private async Task<CodeMetricsInfo> CountLinesAsync(Project project, ICodeMetric
             codeMetrics.TotalLineCount);
 
         WriteLine(Verbosity.Minimal);
-        WriteLine($"Done counting logical lines for '{project.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Normal);
+        LogHelpers.WriteElapsedTime($"Counted logical lines for '{project.FilePath}'", stopwatch.Elapsed, Verbosity.Normal);
 
         return codeMetrics;
     }
 
     private async Task<ImmutableDictionary<ProjectId, CodeMetricsInfo>> CountLinesAsync(Solution solution, CodeMetricsOptions options, CancellationToken cancellationToken)
     {
-        WriteLine($"Count logical lines for solution '{solution.FilePath}'", ConsoleColors.Cyan, Verbosity.Minimal);
+        WriteLine($"Counting logical lines for solution '{solution.FilePath}'...", ConsoleColors.Cyan, Verbosity.Minimal);
 
         IEnumerable<Project> projects = FilterProjects(solution);
 
@@ -111,7 +111,7 @@ private async Task<CodeMetricsInfo> CountLinesAsync(Project project, ICodeMetric
             codeMetrics.Sum(f => f.Value.TotalLineCount));
 
         WriteLine(Verbosity.Minimal);
-        WriteLine($"Done counting logical lines for solution '{solution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Normal);
+        LogHelpers.WriteElapsedTime($"Counted logical lines for solution '{solution.FilePath}'", stopwatch.Elapsed, Verbosity.Normal);
 
         return codeMetrics;
     }
@@ -157,9 +157,4 @@ protected override void ProcessResults(IList<LinesOfCodeCommandResult> results)
             totalPreprocessorDirectiveLineCount: results.Sum(f => f.Metrics.PreprocessorDirectiveLineCount),
             totalLineCount: results.Sum(f => f.Metrics.TotalLineCount));
     }
-
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Logical lines counting was canceled.", Verbosity.Quiet);
-    }
 }
diff --git a/src/CommandLine/Commands/MSBuildWorkspaceCommand.cs b/src/CommandLine/Commands/MSBuildWorkspaceCommand.cs
@@ -227,7 +227,7 @@ protected virtual void WorkspaceFailed(object sender, WorkspaceDiagnosticEventAr
     {
         bool isSolution = string.Equals(Path.GetExtension(path), ".sln", StringComparison.OrdinalIgnoreCase);
 
-        WriteLine($"Load {((isSolution) ? "solution" : "project")} '{path}'", Verbosity.Minimal);
+        WriteLine($"Loading {((isSolution) ? "solution" : "project")} '{path}'...", Verbosity.Minimal);
 
         ProjectOrSolution projectOrSolution;
 
@@ -247,8 +247,6 @@ protected virtual void WorkspaceFailed(object sender, WorkspaceDiagnosticEventAr
             throw new ProjectOrSolutionLoadException($"Error occurred while loading {((isSolution) ? "solution" : "project")} '{path}'", ex);
         }
 
-        WriteLine($"Done loading {((projectOrSolution.IsSolution) ? "solution" : "project")} '{projectOrSolution.FilePath}'", Verbosity.Minimal);
-
         return projectOrSolution;
     }
 
@@ -379,7 +377,7 @@ private protected bool IsMatch(Project project)
 
             Solution solution = projectOrSolution.AsSolution();
 
-            WriteLine($"Compile solution '{solution.FilePath}'", Verbosity.Minimal);
+            WriteLine($"Compiling solution '{solution.FilePath}'", Verbosity.Minimal);
 
             Stopwatch stopwatch = Stopwatch.StartNew();
 
@@ -401,7 +399,7 @@ private protected bool IsMatch(Project project)
 
             stopwatch.Stop();
 
-            WriteLine($"Done compiling solution '{solution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+            LogHelpers.WriteElapsedTime($"Compiled solution '{solution.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
 
             return compilations.ToImmutableArray();
         }

diff --git a/src/CommandLine/Commands/PhysicalLinesOfCodeCommand.cs b/src/CommandLine/Commands/PhysicalLinesOfCodeCommand.cs
@@ -62,7 +62,7 @@ public override async Task<LinesOfCodeCommandResult> ExecuteAsync(ProjectOrSolut
 
     private async Task<CodeMetricsInfo> CountLinesAsync(Project project, ICodeMetricsService service, CodeMetricsOptions options, CancellationToken cancellationToken)
     {
-        WriteLine($"Count lines for '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
+        WriteLine($"Counting lines for '{project.Name}'...", ConsoleColors.Cyan, Verbosity.Minimal);
 
         Stopwatch stopwatch = Stopwatch.StartNew();
 
@@ -84,14 +84,14 @@ private async Task<CodeMetricsInfo> CountLinesAsync(Project project, ICodeMetric
             codeMetrics.TotalLineCount);
 
         WriteLine(Verbosity.Minimal);
-        WriteLine($"Done counting lines for '{project.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Normal);
+        LogHelpers.WriteElapsedTime($"Counted lines for '{project.FilePath}'", stopwatch.Elapsed, Verbosity.Normal);
 
         return codeMetrics;
     }
 
     private async Task<ImmutableDictionary<ProjectId, CodeMetricsInfo>> CountLinesAsync(Solution solution, CodeMetricsOptions options, CancellationToken cancellationToken)
     {
-        WriteLine($"Count lines for solution '{solution.FilePath}'", ConsoleColors.Cyan, Verbosity.Minimal);
+        WriteLine($"Counting lines for solution '{solution.FilePath}'...", ConsoleColors.Cyan, Verbosity.Minimal);
 
         IEnumerable<Project> projects = FilterProjects(solution);
 
@@ -118,7 +118,7 @@ private async Task<CodeMetricsInfo> CountLinesAsync(Project project, ICodeMetric
             codeMetrics.Sum(f => f.Value.TotalLineCount));
 
         WriteLine(Verbosity.Minimal);
-        WriteLine($"Done counting lines for solution '{solution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+        LogHelpers.WriteElapsedTime($"Counted lines for solution '{solution.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
 
         return codeMetrics;
     }
@@ -184,9 +184,4 @@ protected override void ProcessResults(IList<LinesOfCodeCommandResult> results)
             totalPreprocessorDirectiveLineCount: results.Sum(f => f.Metrics.PreprocessorDirectiveLineCount),
             totalLineCount: results.Sum(f => f.Metrics.TotalLineCount));
     }
-
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Lines counting was canceled.", Verbosity.Quiet);
-    }
 }
diff --git a/src/CommandLine/Commands/RenameSymbolCommand.cs b/src/CommandLine/Commands/RenameSymbolCommand.cs
@@ -61,15 +61,15 @@ public override async Task<RenameSymbolCommandResult> ExecuteAsync(ProjectOrSolu
 
             renamer = GetSymbolRenamer(solution);
 
-            WriteLine($"Fix '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
+            WriteLine($"Analyze '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
 
             Stopwatch stopwatch = Stopwatch.StartNew();
 
             await renamer.RenameSymbolsAsync(project, cancellationToken);
 
             stopwatch.Stop();
 
-            WriteLine($"Done fixing project '{project.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+            LogHelpers.WriteElapsedTime($"Analyzed project '{project.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
         }
         else
         {
@@ -111,9 +111,4 @@ SymbolRenameState GetSymbolRenamer(Solution solution)
                 options: options);
         }
     }
-
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Renaming was canceled.", Verbosity.Minimal);
-    }
 }
diff --git a/src/CommandLine/Commands/SpellcheckCommand.cs b/src/CommandLine/Commands/SpellcheckCommand.cs
@@ -89,15 +89,15 @@ public override async Task<SpellcheckCommandResult> ExecuteAsync(ProjectOrSoluti
 
             spellingFixer = GetSpellingFixer(solution);
 
-            WriteLine($"Fix '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
+            WriteLine($"Analyze '{project.Name}'", ConsoleColors.Cyan, Verbosity.Minimal);
 
             Stopwatch stopwatch = Stopwatch.StartNew();
 
             results = await spellingFixer.FixProjectAsync(project, cancellationToken);
 
             stopwatch.Stop();
 
-            WriteLine($"Done fixing project '{project.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+            LogHelpers.WriteElapsedTime($"Analyzed project '{project.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
         }
         else
         {
@@ -128,11 +128,6 @@ SpellcheckAnalyzer GetSpellingFixer(Solution solution)
         }
     }
 
-    protected override void OperationCanceled(OperationCanceledException ex)
-    {
-        WriteLine("Spellchecking was canceled.", Verbosity.Minimal);
-    }
-
     private void WriteSummary(ImmutableArray<SpellingFixResult> results)
     {
         if (!ShouldWrite(Verbosity.Normal))

diff --git a/src/CommandLine/Rename/CliSymbolRenameState.cs b/src/CommandLine/Rename/CliSymbolRenameState.cs
@@ -73,13 +73,13 @@ internal class CliSymbolRenameState : SymbolRenameState
 
                 await AnalyzeProjectAsync(project, renameScopes[i], cancellationToken);
 
-                WriteLine($"  Done renaming {GetScopePluralName(renameScopes[i])} in '{project.Name}' in {stopwatch.Elapsed - lastElapsed:mm\\:ss\\.ff}", Verbosity.Normal);
+                LogHelpers.WriteElapsedTime($"  Renamed {GetScopePluralName(renameScopes[i])} in '{project.Name}'", stopwatch.Elapsed - lastElapsed, Verbosity.Normal);
             }
         }
 
         stopwatch.Stop();
 
-        WriteLine($"Done renaming symbols in solution '{CurrentSolution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+        LogHelpers.WriteElapsedTime($"Renamed symbols in solution '{CurrentSolution.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
     }
 
     public override async Task RenameSymbolsAsync(Project project, CancellationToken cancellationToken = default)

diff --git a/src/CommandLine/Xml/AnalyzerAssemblyXmlSerializer.cs b/src/CommandLine/Xml/AnalyzerAssemblyXmlSerializer.cs
@@ -255,7 +255,7 @@ private static XElement SerializeFixAllProvider(FixAllProvider fixAllProvider)
                     diagnostics,
                     fixAllProviders)));
 
-        WriteLine($"Save analyzer assembly analysis to '{filePath}'", ConsoleColors.DarkGray, Verbosity.Diagnostic);
+        WriteLine($"Saving analyzer assembly analysis to '{filePath}'...", ConsoleColors.DarkGray, Verbosity.Diagnostic);
 
         using (var fileStream = new FileStream(filePath, FileMode.Create))
         using (XmlWriter xmlWriter = XmlWriter.Create(fileStream, new XmlWriterSettings() { Indent = true, CloseOutput = false }))

diff --git a/src/CommandLine/Xml/DiagnosticXmlSerializer.cs b/src/CommandLine/Xml/DiagnosticXmlSerializer.cs
@@ -122,7 +122,7 @@ private static void SerializeDocument(string filePath, XElement summary, params
                     summary,
                     new XElement("Projects", projects))));
 
-        WriteLine($"Save code analysis to '{filePath}'", ConsoleColors.DarkGray, Verbosity.Diagnostic);
+        WriteLine($"Saving code analysis to '{filePath}'...", ConsoleColors.DarkGray, Verbosity.Diagnostic);
 
         using (var fileStream = new FileStream(filePath, FileMode.Create))
         using (XmlWriter xmlWriter = XmlWriter.Create(fileStream, new XmlWriterSettings() { Indent = true, CloseOutput = false }))

diff --git a/src/Workspaces.Core/CodeFixes/CodeFixer.cs b/src/Workspaces.Core/CodeFixes/CodeFixer.cs
@@ -64,7 +64,7 @@ public async Task<ImmutableArray<ProjectFixResult>> FixSolutionAsync(Func<Projec
 
             if (predicate is null || predicate(project))
             {
-                WriteLine($"Fix '{project.Name}' {$"{i + 1}/{projects.Length}"}", ConsoleColors.Cyan, Verbosity.Minimal);
+                WriteLine($"Analyze '{project.Name}' {$"{i + 1}/{projects.Length}"}", ConsoleColors.Cyan, Verbosity.Minimal);
 
                 ProjectFixResult result = await FixProjectAsync(project, cancellationToken).ConfigureAwait(false);
 
@@ -75,21 +75,21 @@ public async Task<ImmutableArray<ProjectFixResult>> FixSolutionAsync(Func<Projec
             }
             else
             {
-                WriteLine($"Skip '{project.Name}' {$"{i + 1}/{projects.Length}"}", ConsoleColors.DarkGray, Verbosity.Minimal);
+                WriteLine($"Skipping '{project.Name}' {$"{i + 1}/{projects.Length}"}", ConsoleColors.DarkGray, Verbosity.Minimal);
 
                 results.Add(ProjectFixResult.Skipped);
             }
 
             TimeSpan elapsed = stopwatch.Elapsed;
 
-            WriteLine($"Done fixing '{project.Name}' in {elapsed - lastElapsed:mm\\:ss\\.ff}", Verbosity.Normal);
+            LogHelpers.WriteElapsedTime($"Analyzed '{project.Name}'", elapsed - lastElapsed, Verbosity.Normal);
 
             lastElapsed = elapsed;
         }
 
         stopwatch.Stop();
 
-        WriteLine($"Done fixing solution '{CurrentSolution.FilePath}' in {stopwatch.Elapsed:mm\\:ss\\.ff}", Verbosity.Minimal);
+        LogHelpers.WriteElapsedTime($"Analyzed solution '{CurrentSolution.FilePath}'", stopwatch.Elapsed, Verbosity.Minimal);
 
         return results.ToImmutableArray();
     }
@@ -598,7 +598,7 @@ private bool VerifyCompilerDiagnostics(ImmutableArray<Diagnostic> diagnostics, P
 
             Document newDocument = document.WithSyntaxRoot(newRoot);
 
-            WriteLine($"  Add banner to '{PathUtilities.TrimStart(document.FilePath!, solutionDirectory)}'", ConsoleColors.DarkGray, Verbosity.Detailed);
+            WriteLine($"  Added banner to '{PathUtilities.TrimStart(document.FilePath!, solutionDirectory)}'", ConsoleColors.DarkGray, Verbosity.Detailed);
 
             project = newDocument.Project;