Improve progress output, fix potential race condition while rebuilding multiple projects

Author: tmat

src/BuiltInTools/dotnet-watch/Build/BuildReporter.cs

@@ -102,7 +102,7 @@ private void Write(string message)
         public void ReportOutput()
         {
             _logger.LogInformation("MSBuild output:");
-            BuildOutput.ReportBuildOutput(_logger, Messages, success: false, projectDisplay: null);
+            BuildOutput.ReportBuildOutput(_logger, Messages, success: false);
         }
     }
 }

src/BuiltInTools/dotnet-watch/CommandLine/EnvironmentOptions.cs

@@ -12,21 +12,16 @@ internal enum TestFlags
         RunningAsTest = 1 << 0,
         MockBrowser = 1 << 1,
 
-        /// <summary>
-        /// Elevates the severity of <see cref="MessageDescriptor.WaitingForChanges"/> from <see cref="MessageSeverity.Output"/>.
-        /// </summary>
-        ElevateWaitingForChangesMessageSeverity = 1 << 2,
-
         /// <summary>
         /// Instead of using <see cref="Console.ReadKey()"/> to watch for Ctrl+C, Ctlr+R, and other keys, read from standard input.
         /// This allows tests to trigger key based events.
         /// </summary>
-        ReadKeyFromStdin = 1 << 3,
+        ReadKeyFromStdin = 1 << 2,
 
         /// <summary>
         /// Redirects the output of the launched browser process to watch output.
         /// </summary>
-        RedirectBrowserOutput = 1 << 4,
+        RedirectBrowserOutput = 1 << 3,
     }
 
     internal sealed record EnvironmentOptions(

src/BuiltInTools/dotnet-watch/HotReload/HotReloadDotNetWatcher.cs

@@ -82,8 +82,7 @@ public async Task WatchAsync(CancellationToken shutdownCancellationToken)
                 {
                     var rootProjectOptions = _context.RootProjectOptions;
 
-                    var (buildSucceeded, buildOutput, _) = await BuildProjectAsync(rootProjectOptions.ProjectPath, rootProjectOptions.BuildArguments, iterationCancellationToken);
-                    BuildOutput.ReportBuildOutput(_context.BuildLogger, buildOutput, buildSucceeded, projectDisplay: rootProjectOptions.ProjectPath);
+                    var buildSucceeded = await BuildProjectAsync(rootProjectOptions.ProjectPath, rootProjectOptions.BuildArguments, iterationCancellationToken);
                     if (!buildSucceeded)
                     {
                         continue;
@@ -189,7 +188,7 @@ void FileChangedCallback(ChangedPath change)
 
                     fileChangedCallback = FileChangedCallback;
                     fileWatcher.OnFileChange += fileChangedCallback;
-                    ReportWatchingForChanges();
+                    _context.Logger.Log(MessageDescriptor.WaitingForChanges);
 
                     // Hot Reload loop - exits when the root process needs to be restarted.
                     bool extendTimeout = false;
@@ -328,15 +327,19 @@ void FileChangedCallback(ChangedPath change)
                                 fileWatcher.SuppressEvents = true;
                                 try
                                 {
-                                    var buildResults = await Task.WhenAll(
-                                        projectsToRebuild.Select(projectPath => BuildProjectAsync(projectPath, rootProjectOptions.BuildArguments, iterationCancellationToken)));
-
-                                    foreach (var (success, output, projectPath) in buildResults)
+                                    // Build projects sequentially to avoid failed attempts to overwrite dependent project outputs.
+                                    // TODO: Ideally, dotnet build would be able to build multiple projects.
+                                    var success = true;
+                                    foreach (var projectPath in projectsToRebuild)
                                     {
-                                        BuildOutput.ReportBuildOutput(_context.BuildLogger, output, success, projectPath);
+                                        success = await BuildProjectAsync(projectPath, rootProjectOptions.BuildArguments, iterationCancellationToken);
+                                        if (!success)
+                                        {
+                                            break;
+                                        }
                                     }
 
-                                    if (buildResults.All(result => result.success))
+                                    if (success)
                                     {
                                         break;
                                     }
@@ -772,12 +775,6 @@ internal static IEnumerable<ChangedPath> NormalizePathChanges(IEnumerable<Change
                 .Where(item => item != null)
                 .Select(item => item!.Value);
 
-        private void ReportWatchingForChanges()
-        {
-            _context.Logger.Log(MessageDescriptor.WaitingForChanges
-                .WithSeverityWhen(MessageSeverity.Output, _context.EnvironmentOptions.TestFlags.HasFlag(TestFlags.ElevateWaitingForChangesMessageSeverity)));
-        }
-
         private void ReportFileChanges(IReadOnlyList<ChangedFile> changedFiles)
         {
             Report(kind: ChangeKind.Add);
@@ -823,6 +820,9 @@ private async ValueTask<EvaluationResult> EvaluateRootProjectAsync(bool restore,
             {
                 cancellationToken.ThrowIfCancellationRequested();
 
+                _context.Logger.LogInformation("Evaluating projects ...");
+                var stopwatch = Stopwatch.StartNew();
+
                 var result = EvaluationResult.TryCreate(
                     _context.RootProjectOptions.ProjectPath,
                     _context.RootProjectOptions.BuildArguments,
@@ -832,6 +832,8 @@ private async ValueTask<EvaluationResult> EvaluateRootProjectAsync(bool restore,
                     restore,
                     cancellationToken);
 
+                _context.Logger.LogInformation("Evaluation completed in {Time}s.", stopwatch.Elapsed.TotalSeconds.ToString("0.0"));
+
                 if (result != null)
                 {
                     return result;
@@ -846,31 +848,43 @@ await FileWatcher.WaitForFileChangeAsync(
             }
         }
 
-        private async Task<(bool success, ImmutableArray<OutputLine> output, string projectPath)> BuildProjectAsync(
-            string projectPath, IReadOnlyList<string> buildArguments, CancellationToken cancellationToken)
+        private async Task<bool> BuildProjectAsync(string projectPath, IReadOnlyList<string> buildArguments, CancellationToken cancellationToken)
         {
-            var buildOutput = new List<OutputLine>();
+            List<OutputLine>? capturedOutput = _context.EnvironmentOptions.TestFlags != TestFlags.None ? [] : null;
 
             var processSpec = new ProcessSpec
             {
                 Executable = _context.EnvironmentOptions.MuxerPath,
                 WorkingDirectory = Path.GetDirectoryName(projectPath)!,
                 IsUserApplication = false,
-                OnOutput = line =>
-                {
-                    lock (buildOutput)
+
+                // Capture output if running in a test environment.
+                // If the output is not captured dotnet build will show live build progress.
+                OnOutput = capturedOutput != null
+                    ? line =>
                     {
-                        buildOutput.Add(line);
+                        lock (capturedOutput)
+                        {
+                            capturedOutput.Add(line);
+                        }
                     }
-                },
+                    : null,
+
                 // pass user-specified build arguments last to override defaults:
                 Arguments = ["build", projectPath, "-consoleLoggerParameters:NoSummary;Verbosity=minimal", .. buildArguments]
             };
 
             _context.BuildLogger.Log(MessageDescriptor.Building, projectPath);
 
-            var exitCode = await _context.ProcessRunner.RunAsync(processSpec, _context.Logger, launchResult: null, cancellationToken);
-            return (exitCode == 0, buildOutput.ToImmutableArray(), projectPath);
+            var success = await _context.ProcessRunner.RunAsync(processSpec, _context.Logger, launchResult: null, cancellationToken) == 0;
+
+            if (capturedOutput != null)
+            {
+                _context.BuildLogger.Log(success ? MessageDescriptor.BuildSucceeded : MessageDescriptor.BuildFailed, projectPath);
+                BuildOutput.ReportBuildOutput(_context.BuildLogger, capturedOutput, success);
+            }
+
+            return success;
         }
 
         private string GetRelativeFilePath(string path)

src/BuiltInTools/dotnet-watch/HotReload/IncrementalMSBuildWorkspace.cs

@@ -15,6 +15,7 @@ namespace Microsoft.DotNet.Watch;
 internal sealed class IncrementalMSBuildWorkspace : Workspace
 {
     private readonly ILogger _logger;
+    private int _solutionUpdateId;
 
     public IncrementalMSBuildWorkspace(ILogger logger)
         : base(MSBuildMefHostServices.DefaultServices, WorkspaceKind.MSBuild)
@@ -35,6 +36,9 @@ public IncrementalMSBuildWorkspace(ILogger logger)
 
     public async Task UpdateProjectConeAsync(string rootProjectPath, CancellationToken cancellationToken)
     {
+        _logger.LogInformation("Loading projects ...");
+
+        var stopwatch = Stopwatch.StartNew();
         var oldSolution = CurrentSolution;
 
         var loader = new MSBuildProjectLoader(this);
@@ -94,9 +98,11 @@ public async Task UpdateProjectConeAsync(string rootProjectPath, CancellationTok
                 .WithCompilationOutputInfo(newProjectInfo.CompilationOutputInfo));
         }
 
-        await ReportSolutionFilesAsync(SetCurrentSolution(newSolution), cancellationToken);
+        await UpdateSolutionAsync(newSolution, operationDisplayName: "project update", cancellationToken);
         UpdateReferencesAfterAdd();
 
+        _logger.LogInformation("Projects loaded in {Time}s.", stopwatch.Elapsed.TotalSeconds.ToString("0.0"));
+
         ProjectReference MapProjectReference(ProjectReference pr)
             // Only C# and VB projects are loaded by the MSBuildProjectLoader, so some references might be missing.
             // When a new project is added along with a new project reference the old project id is also null.
@@ -154,6 +160,8 @@ public async ValueTask UpdateFileContentAsync(IEnumerable<ChangedFile> changedFi
 
                 var newText = await GetSourceTextAsync(changedFile.FilePath, oldText.Encoding, oldText.ChecksumAlgorithm, cancellationToken);
 
+                _logger.LogDebug("Updating document text of '{FilePath}'.", changedFile.FilePath);
+
                 updatedSolution = textDocument switch
                 {
                     Document document => document.WithText(newText).Project.Solution,
@@ -166,7 +174,7 @@ public async ValueTask UpdateFileContentAsync(IEnumerable<ChangedFile> changedFi
 
         updatedSolution = RemoveDocuments(updatedSolution, documentsToRemove);
 
-        await ReportSolutionFilesAsync(SetCurrentSolution(updatedSolution), cancellationToken);
+        await UpdateSolutionAsync(updatedSolution, operationDisplayName: "document update", cancellationToken);
     }
 
     private static Solution RemoveDocuments(Solution solution, IEnumerable<DocumentId> ids)
@@ -217,10 +225,21 @@ private static async ValueTask<SourceText> GetSourceTextAsync(string filePath, E
         return null;
     }
 
-    public async Task ReportSolutionFilesAsync(Solution solution, CancellationToken cancellationToken)
+    private Task UpdateSolutionAsync(Solution newSolution, string operationDisplayName, CancellationToken cancellationToken)
+        => ReportSolutionFilesAsync(SetCurrentSolution(newSolution), Interlocked.Increment(ref _solutionUpdateId), operationDisplayName, cancellationToken);
+
+    private async Task ReportSolutionFilesAsync(Solution solution, int updateId, string operationDisplayName, CancellationToken cancellationToken)
     {
 #if DEBUG
         _logger.LogDebug("Solution: {Path}", solution.FilePath);
+
+        if (!_logger.IsEnabled(LogLevel.Debug))
+        {
+            return;
+        }
+
+        _logger.LogDebug("Solution after {Operation}: v{Version}", operationDisplayName, updateId);
+
         foreach (var project in solution.Projects)
         {
             _logger.LogDebug("  Project: {Path}", project.FilePath);

src/BuiltInTools/dotnet-watch/Properties/launchSettings.json

@@ -2,8 +2,8 @@
   "profiles": {
     "dotnet-watch": {
       "commandName": "Project",
-      "commandLineArgs": "--verbose -bl",
-      "workingDirectory": "C:\\bugs\\9756\\aspire-watch-start-issue\\Aspire.AppHost",
+      "commandLineArgs": "",
+      "workingDirectory": "C:\\temp\\Razor",
       "environmentVariables": {
         "DOTNET_WATCH_DEBUG_SDK_DIRECTORY": "$(RepoRoot)artifacts\\bin\\redist\\$(Configuration)\\dotnet\\sdk\\$(Version)",
         "DCP_IDE_REQUEST_TIMEOUT_SECONDS": "100000",

src/BuiltInTools/dotnet-watch/UI/BuildOutput.cs

@@ -13,20 +13,8 @@ internal static partial class BuildOutput
     [GeneratedRegex(@"[^:]+: (error|warning) [A-Za-z]+[0-9]+: .+")]
     private static partial Regex GetBuildDiagnosticRegex();
 
-    public static void ReportBuildOutput(ILogger logger, IEnumerable<OutputLine> buildOutput, bool success, string? projectDisplay)
+    public static void ReportBuildOutput(ILogger logger, IEnumerable<OutputLine> buildOutput, bool success)
     {
-        if (projectDisplay != null)
-        {
-            if (success)
-            {
-                logger.Log(MessageDescriptor.BuildSucceeded, projectDisplay);
-            }
-            else
-            {
-                logger.Log(MessageDescriptor.BuildFailed, projectDisplay);
-            }
-        }
-
         foreach (var (line, isError) in buildOutput)
         {
             if (isError)

src/BuiltInTools/dotnet-watch/UI/IReporter.cs

@@ -186,7 +186,7 @@ public MessageDescriptor WithSeverityWhen(MessageSeverity severity, bool conditi
         public static readonly MessageDescriptor ProjectsRestarted = Create("Projects restarted ({0})", Emoji.HotReload, MessageSeverity.Verbose);
         public static readonly MessageDescriptor ProjectDependenciesDeployed = Create("Project dependencies deployed ({0})", Emoji.HotReload, MessageSeverity.Verbose);
         public static readonly MessageDescriptor FixBuildError = Create("Fix the error to continue or press Ctrl+C to exit.", Emoji.Watch, MessageSeverity.Warning);
-        public static readonly MessageDescriptor WaitingForChanges = Create("Waiting for changes", Emoji.Watch, MessageSeverity.Verbose);
+        public static readonly MessageDescriptor WaitingForChanges = Create("Waiting for changes", Emoji.Watch, MessageSeverity.Output);
         public static readonly MessageDescriptor LaunchedProcess = Create("Launched '{0}' with arguments '{1}': process id {2}", Emoji.Launch, MessageSeverity.Verbose);
         public static readonly MessageDescriptor HotReloadChangeHandled = Create("Hot reload change handled in {0}ms.", Emoji.HotReload, MessageSeverity.Verbose);
         public static readonly MessageDescriptor HotReloadSucceeded = Create(LogEvents.HotReloadSucceeded, Emoji.HotReload);

src/BuiltInTools/dotnet-watch/Watch/MsBuildFileSetFactory.cs

@@ -73,7 +73,7 @@ internal sealed class EvaluationResult(IReadOnlyDictionary<string, FileItem> fil
                     Logger.LogInformation("MSBuild output from target '{TargetName}':", TargetName);
                 }
 
-                BuildOutput.ReportBuildOutput(Logger, capturedOutput, success, projectDisplay: null);
+                BuildOutput.ReportBuildOutput(Logger, capturedOutput, success);
                 if (!success)
                 {
                     return null;

test/dotnet-watch.Tests/HotReload/ApplyDeltaTests.cs

@@ -755,7 +755,7 @@ class AppUpdateHandler
                 App.DotnetWatchArgs.Clear();
             }
 
-            App.Start(testAsset, [], testFlags: TestFlags.ElevateWaitingForChangesMessageSeverity);
+            App.Start(testAsset, []);
 
             await App.WaitForOutputLineContaining(MessageDescriptor.WaitingForChanges);