Report better warnings and errors if build hosts exit abnormally

src/Workspaces/Core/MSBuild/MSBuild/BuildHostProcessManager.cs

@@ -9,6 +9,7 @@
 using System.IO;
 using System.Linq;
 using System.Runtime.InteropServices;
+using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
 using System.Xml;
@@ -96,8 +97,10 @@ public async Task<RemoteBuildHost> GetBuildHostAsync(BuildHostProcessKind buildH
                 // We've subscribed to Disconnected, but if the process crashed before that point we might have not seen it
                 if (process.HasExited)
                 {
+                    buildHostProcess.LogProcessFailure();
                     throw new Exception($"BuildHost process exited immediately with {process.ExitCode}");
                 }
+
                 _processes.Add(buildHostKind, buildHostProcess);
             }
 
@@ -127,7 +130,7 @@ private void BuildHostProcess_Disconnected(object? sender, EventArgs e)
             // Dispose outside of the lock (even though we don't expect much to happen at this point)
             if (processToDispose != null)
             {
-                processToDispose.LoggerForProcessMessages?.LogTrace("Process exited.");
+                processToDispose.LogProcessFailure();
                 await processToDispose.DisposeAsync().ConfigureAwait(false);
             }
         });
@@ -328,15 +331,21 @@ public enum BuildHostProcessKind
 
     private sealed class BuildHostProcess : IAsyncDisposable
     {
+        private readonly ILogger? _logger;
         private readonly Process _process;
         private readonly RpcClient _rpcClient;
 
+        /// <summary>
+        /// A string builder where we collect the process log messages, in case we do want to know them if the process crashes.
+        /// Reads/writes should be synchronized by locking this object.
+        /// </summary>
+        private readonly StringBuilder _processLogMessages = new();
+
         private int _disposed = 0;
 
         public BuildHostProcess(Process process, ILoggerFactory? loggerFactory)
         {
-            LoggerForProcessMessages = loggerFactory?.CreateLogger($"BuildHost PID {process.Id}");
-
+            _logger = loggerFactory?.CreateLogger($"BuildHost PID {process.Id}");
             _process = process;
 
             _process.EnableRaisingEvents = true;
@@ -361,11 +370,15 @@ private void Process_Exited(object? sender, EventArgs e)
         private void Process_ErrorDataReceived(object sender, DataReceivedEventArgs e)
         {
             if (e.Data is not null)
-                LoggerForProcessMessages?.LogTrace($"Message from Process: {e.Data}");
+            {
+                lock (_processLogMessages)
+                    _processLogMessages.AppendLine(e.Data);
+
+                _logger?.LogTrace($"Message from Process: {e.Data}");
+            }
         }
 
         public RemoteBuildHost BuildHost { get; }
-        public ILogger? LoggerForProcessMessages { get; }
 
         public event EventHandler? Disconnected;
 
@@ -380,23 +393,39 @@ public async ValueTask DisposeAsync()
             {
                 if (!_process.HasExited)
                 {
-                    LoggerForProcessMessages?.LogTrace("Sending a Shutdown request to the BuildHost.");
+                    _logger?.LogTrace("Sending a Shutdown request to the BuildHost.");
 
                     await BuildHost.ShutdownAsync(CancellationToken.None).ConfigureAwait(false);
                 }
 
                 _rpcClient.Shutdown();
 
-                LoggerForProcessMessages?.LogTrace("Process shut down.");
+                _logger?.LogTrace("Process shut down.");
             }
             catch (Exception e)
             {
-                LoggerForProcessMessages?.LogError(e, "Exception while shutting down the BuildHost process.");
+                _logger?.LogError(e, "Exception while shutting down the BuildHost process.");
 
-                // OK, process may have gone bad.
+                // Process may have gone bad, so not much else we can do.
+                LogProcessFailure();
                 _process.Kill();
             }
         }
+
+        public void LogProcessFailure()
+        {
+            if (_logger == null)
+                return;
+
+            string processLog;
+            lock (_processLogMessages)
+                processLog = _processLogMessages.ToString();
+
+            if (!_process.HasExited)
+                _logger.LogError("The BuildHost process is not responding. Process output:{newLine}{processLog}", Environment.NewLine, processLog);
+            else if (_process.ExitCode != 0)
+                _logger.LogError("The BuildHost process exited with {errorCode}. Process output:{newLine}{processLog}", _process.ExitCode, Environment.NewLine, processLog);
+        }
     }
 }
 

src/Workspaces/Core/MSBuild/MSBuild/DiagnosticReporterLoggerProvider.cs

@@ -0,0 +1,58 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+// See the LICENSE file in the project root for more information.
+
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.CodeAnalysis.MSBuild;
+
+internal class DiagnosticReporterLoggerProvider : ILoggerProvider
+{
+    private readonly DiagnosticReporter _reporter;
+
+    private DiagnosticReporterLoggerProvider(DiagnosticReporter reporter)
+    {
+        _reporter = reporter;
+    }
+
+    public ILogger CreateLogger(string categoryName)
+    {
+        return new Logger(_reporter, categoryName);
+    }
+
+    public void Dispose()
+    {
+    }
+
+    public static ILoggerFactory CreateLoggerFactoryForDiagnosticReporter(DiagnosticReporter reporter)
+    {
+        // Note: it's important we set MinLevel here, or otherwise we'll still get called in Log() for things below LogLevel.Warning.
+        return new LoggerFactory(
+            [new DiagnosticReporterLoggerProvider(reporter)],
+            new LoggerFilterOptions() { MinLevel = LogLevel.Warning });
+    }
+
+    private sealed class Logger(DiagnosticReporter reporter, string categoryName) : ILogger
+    {
+        public IDisposable? BeginScope<TState>(TState state) where TState : notnull
+        {
+            return null;
+        }
+
+        public bool IsEnabled(LogLevel logLevel)
+        {
+            return logLevel >= LogLevel.Warning;
+        }
+
+        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
+        {
+            var kind = logLevel == LogLevel.Warning ? WorkspaceDiagnosticKind.Warning : WorkspaceDiagnosticKind.Failure;
+            var message = formatter(state, exception);
+            if (!string.IsNullOrEmpty(categoryName))
+                message = $"[{categoryName}] {message}";
+
+            reporter.Report(new WorkspaceDiagnostic(kind, message));
+        }
+    }
+}

src/Workspaces/Core/MSBuild/MSBuild/MSBuildProjectLoader.cs

@@ -9,7 +9,6 @@
 using System.Threading.Tasks;
 using Microsoft.Build.Framework;
 using Microsoft.CodeAnalysis.Host;
-using Microsoft.CodeAnalysis.MSBuild.Build;
 using Roslyn.Utilities;
 using MSB = Microsoft.Build;
 
@@ -24,6 +23,7 @@ public partial class MSBuildProjectLoader
         private readonly SolutionServices _solutionServices;
 
         private readonly DiagnosticReporter _diagnosticReporter;
+        private readonly Microsoft.Extensions.Logging.ILoggerFactory _loggerFactory;
         private readonly PathResolver _pathResolver;
         private readonly ProjectFileExtensionRegistry _projectFileExtensionRegistry;
 
@@ -33,13 +33,15 @@ public partial class MSBuildProjectLoader
         internal MSBuildProjectLoader(
             SolutionServices solutionServices,
             DiagnosticReporter diagnosticReporter,
-            ProjectFileExtensionRegistry? projectFileExtensionRegistry,
+            Microsoft.Extensions.Logging.ILoggerFactory loggerFactory,
+            ProjectFileExtensionRegistry projectFileExtensionRegistry,
             ImmutableDictionary<string, string>? properties)
         {
             _solutionServices = solutionServices;
             _diagnosticReporter = diagnosticReporter;
+            _loggerFactory = loggerFactory;
             _pathResolver = new PathResolver(_diagnosticReporter);
-            _projectFileExtensionRegistry = projectFileExtensionRegistry ?? new ProjectFileExtensionRegistry(solutionServices, _diagnosticReporter);
+            _projectFileExtensionRegistry = projectFileExtensionRegistry;
 
             Properties = ImmutableDictionary.Create<string, string>(StringComparer.OrdinalIgnoreCase);
 
@@ -56,8 +58,19 @@ internal MSBuildProjectLoader(
         /// <param name="properties">An optional dictionary of additional MSBuild properties and values to use when loading projects.
         /// These are the same properties that are passed to MSBuild via the /property:&lt;n&gt;=&lt;v&gt; command line argument.</param>
         public MSBuildProjectLoader(Workspace workspace, ImmutableDictionary<string, string>? properties = null)
-            : this(workspace.Services.SolutionServices, new DiagnosticReporter(workspace), projectFileExtensionRegistry: null, properties)
         {
+            _solutionServices = workspace.Services.SolutionServices;
+            _diagnosticReporter = new DiagnosticReporter(workspace);
+            _loggerFactory = DiagnosticReporterLoggerProvider.CreateLoggerFactoryForDiagnosticReporter(_diagnosticReporter);
+            _pathResolver = new PathResolver(_diagnosticReporter);
+            _projectFileExtensionRegistry = new ProjectFileExtensionRegistry(_solutionServices, _diagnosticReporter);
+
+            Properties = ImmutableDictionary.Create<string, string>(StringComparer.OrdinalIgnoreCase);
+
+            if (properties != null)
+            {
+                Properties = Properties.AddRange(properties);
+            }
         }
 
         /// <summary>
@@ -199,7 +212,7 @@ public async Task<SolutionInfo> LoadSolutionInfoAsync(
                 }
             }
 
-            var buildHostProcessManager = new BuildHostProcessManager(Properties);
+            var buildHostProcessManager = new BuildHostProcessManager(Properties, loggerFactory: _loggerFactory);
             await using var _ = buildHostProcessManager.ConfigureAwait(false);
 
             var worker = new Worker(
@@ -261,7 +274,7 @@ public async Task<ImmutableArray<ProjectInfo>> LoadProjectInfoAsync(
                 onPathFailure: reportingMode,
                 onLoaderFailure: reportingMode);
 
-            var buildHostProcessManager = new BuildHostProcessManager(Properties);
+            var buildHostProcessManager = new BuildHostProcessManager(Properties, loggerFactory: _loggerFactory);
             await using var _ = buildHostProcessManager.ConfigureAwait(false);
 
             var worker = new Worker(

src/Workspaces/Core/MSBuild/MSBuild/MSBuildWorkspace.cs

@@ -31,6 +31,7 @@ public sealed class MSBuildWorkspace : Workspace
         private readonly NonReentrantLock _serializationLock = new();
 
         private readonly MSBuildProjectLoader _loader;
+        private readonly Microsoft.Extensions.Logging.ILoggerFactory _loggerFactory;
         private readonly ProjectFileExtensionRegistry _projectFileExtensionRegistry;
         private readonly DiagnosticReporter _reporter;
 
@@ -41,7 +42,8 @@ private MSBuildWorkspace(
         {
             _reporter = new DiagnosticReporter(this);
             _projectFileExtensionRegistry = new ProjectFileExtensionRegistry(Services.SolutionServices, _reporter);
-            _loader = new MSBuildProjectLoader(Services.SolutionServices, _reporter, _projectFileExtensionRegistry, properties);
+            _loggerFactory = DiagnosticReporterLoggerProvider.CreateLoggerFactoryForDiagnosticReporter(_reporter);
+            _loader = new MSBuildProjectLoader(Services.SolutionServices, _reporter, _loggerFactory, _projectFileExtensionRegistry, properties);
         }
 
         /// <summary>
@@ -312,7 +314,7 @@ internal override bool TryApplyChanges(Solution newSolution, IProgress<CodeAnaly
                 try
                 {
                     Debug.Assert(_applyChangesBuildHostProcessManager == null);
-                    _applyChangesBuildHostProcessManager = new BuildHostProcessManager(Properties);
+                    _applyChangesBuildHostProcessManager = new BuildHostProcessManager(Properties, loggerFactory: _loggerFactory);
 
                     return base.TryApplyChanges(newSolution, progressTracker);
                 }

src/Workspaces/MSBuildTest/VisualStudioMSBuildWorkspaceTests.cs

@@ -90,6 +90,20 @@ public async Task TestOpenSolution_MultiProjectSolution()
             Assert.Equal(5, compReferences.Count);
         }
 
+        [ConditionalFact(typeof(VisualStudioMSBuildInstalled))]
+        public async Task TestDirectUseOfMSBuildProjectLoader()
+        {
+            CreateFiles(GetSimpleCSharpSolutionFiles());
+            var solutionFilePath = GetSolutionFileName("TestSolution.sln");
+
+            using var workspace = CreateMSBuildWorkspace();
+            var msbuildProjectLoader = new MSBuildProjectLoader(workspace);
+            var solutionInfo = await msbuildProjectLoader.LoadSolutionInfoAsync(solutionFilePath);
+            var projectInfo = Assert.Single(solutionInfo.Projects);
+
+            Assert.Single(projectInfo.Documents.Where(d => d.Name == "CSharpClass.cs"));
+        }
+
         [ConditionalFact(typeof(VisualStudioMSBuildInstalled))]
         public async Task Test_SharedMetadataReferences()
         {
@@ -2349,18 +2363,18 @@ public async Task TestLoadTextSync()
 
             CreateFiles(files);
 
-            using var workspace = new AdhocWorkspace(MSBuildMefHostServices.DefaultServices, WorkspaceKind.MSBuild);
+            using var workspace = CreateMSBuildWorkspace();
             var projectFullPath = GetSolutionFileName(@"AnalyzerSolution\CSharpProject_AnalyzerReference.csproj");
 
-            var loader = new MSBuildProjectLoader(workspace);
-            var infos = await loader.LoadProjectInfoAsync(projectFullPath);
+            var project = await workspace.OpenProjectAsync(projectFullPath);
 
-            var doc = infos[0].Documents[0];
-            var tav = doc.TextLoader.LoadTextAndVersionSynchronously(new LoadTextOptions(SourceHashAlgorithms.Default), CancellationToken.None);
+            var document = project.Documents.Single(d => d.Name == "CSharpClass.cs");
+            var documentText = document.GetTextSynchronously(CancellationToken.None);
+            Assert.Contains("public class CSharpClass", documentText.ToString(), StringComparison.Ordinal);
 
-            var adoc = infos[0].AdditionalDocuments.First(a => a.Name == "XamlFile.xaml");
-            var atav = adoc.TextLoader.LoadTextAndVersionSynchronously(new LoadTextOptions(SourceHashAlgorithms.Default), CancellationToken.None);
-            Assert.Contains("Window", atav.Text.ToString(), StringComparison.Ordinal);
+            var additionalDocument = project.AdditionalDocuments.Single(a => a.Name == "XamlFile.xaml");
+            var additionalDocumentText = additionalDocument.GetTextSynchronously(CancellationToken.None);
+            Assert.Contains("Window", additionalDocumentText.ToString(), StringComparison.Ordinal);
         }
 
         [ConditionalFact(typeof(VisualStudioMSBuildInstalled))]