Pipe is broken exception in MSBuildWorkspace tests

[jasonmalinowski]

We're seeing this randomly in CI, often in our Spanish queue:

System.AggregateException : An error occurred while writing to logger(s). (Workspace failure Failure:[BuildHost PID 996] Exception while shutting down the BuildHost process.
System.IO.IOException: Pipe is broken.
   at System.IO.Pipes.PipeStream.CheckWriteOperations()
   at System.IO.Pipes.PipeStream.FlushAsync(CancellationToken cancellationToken)
--- End of stack trace from previous location ---
   at System.IO.StreamWriter.<FlushAsyncInternal>g__Core|79_0(Boolean flushStream, Boolean flushEncoder, CancellationToken cancellationToken)
   at Microsoft.CodeAnalysis.MSBuild.RpcClient.InvokeCoreAsync(Int32 targetObject, String methodName, List`1 parameters, Type expectedReturnType, CancellationToken cancellationToken) in /_/src/Workspaces/MSBuild/Core/Rpc/RpcClient.cs:line 166
   at Microsoft.CodeAnalysis.MSBuild.BuildHostProcessManager.BuildHostProcess.DisposeAsync() in /_/src/Workspaces/MSBuild/Core/MSBuild/BuildHostProcessManager.cs:line 434)
---- System.Exception : Workspace failure Failure:[BuildHost PID 996] Exception while shutting down the BuildHost process.
System.IO.IOException: Pipe is broken.
   at System.IO.Pipes.PipeStream.CheckWriteOperations()
   at System.IO.Pipes.PipeStream.FlushAsync(CancellationToken cancellationToken)
--- End of stack trace from previous location ---
   at System.IO.StreamWriter.<FlushAsyncInternal>g__Core|79_0(Boolean flushStream, Boolean flushEncoder, CancellationToken cancellationToken)
   at Microsoft.CodeAnalysis.MSBuild.RpcClient.InvokeCoreAsync(Int32 targetObject, String methodName, List`1 parameters, Type expectedReturnType, CancellationToken cancellationToken) in /_/src/Workspaces/MSBuild/Core/Rpc/RpcClient.cs:line 166
   at Microsoft.CodeAnalysis.MSBuild.BuildHostProcessManager.BuildHostProcess.DisposeAsync() in /_/src/Workspaces/MSBuild/Core/MSBuild/BuildHostProcessManager.cs:line 434
  Seguimiento de la pila:
     at Microsoft.Extensions.Logging.Logger.ThrowLoggingError(List`1 exceptions)
   at Microsoft.Extensions.Logging.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter)
   at Microsoft.Extensions.Logging.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, EventId eventId, Exception exception, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.Log(ILogger logger, LogLevel logLevel, Exception exception, String message, Object[] args)
   at Microsoft.Extensions.Logging.LoggerExtensions.LogError(ILogger logger, Exception exception, String message, Object[] args)
   at Microsoft.CodeAnalysis.MSBuild.BuildHostProcessManager.BuildHostProcess.DisposeAsync() in /_/src/Workspaces/MSBuild/Core/MSBuild/BuildHostProcessManager.cs:line 443
   at Microsoft.CodeAnalysis.MSBuild.BuildHostProcessManager.DisposeAsync() in /_/src/Workspaces/MSBuild/Core/MSBuild/BuildHostProcessManager.cs:line 162
   at Microsoft.CodeAnalysis.MSBuild.MSBuildProjectLoader.LoadProjectInfoAsync(String projectFilePath, ProjectMap projectMap, IProgress`1 progress, ILogger msbuildLogger, CancellationToken cancellationToken) in /_/src/Workspaces/MSBuild/Core/MSBuild/MSBuildProjectLoader.cs:line 295
   at Microsoft.CodeAnalysis.MSBuild.MSBuildWorkspace.OpenProjectAsync(String projectFilePath, ILogger msbuildLogger, IProgress`1 progress, CancellationToken cancellationToken) in /_/src/Workspaces/MSBuild/Core/MSBuild/MSBuildWorkspace.cs:line 251
   at Microsoft.CodeAnalysis.MSBuild.UnitTests.NetCoreTests.TestOpenProject_NetCoreApp() in /_/src/Workspaces/MSBuild/Test/NetCoreTests.cs:line 80
--- End of stack trace from previous location ---
----- Inner Stack Trace -----
   at Microsoft.CodeAnalysis.MSBuild.UnitTests.MSBuildWorkspaceTestBase.<>c.<CreateMSBuildWorkspace>b__14_0(Object s, WorkspaceDiagnosticEventArgs e) in /_/src/Workspaces/MSBuild/Test/MSBuildWorkspaceTestBase.cs:line 154
   at Microsoft.CodeAnalysis.Workspace.<>c.<OnWorkspaceFailed>b__242_0(EventHandler`1 handler, ValueTuple`2 arg) in /_/src/Workspaces/Core/Portable/Workspace/Workspace_Events.cs:line 103
   at Roslyn.Utilities.EventMap.Registry`1.Invoke[TArg](Action`2 invoker, TArg arg) in /_/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Utilities/EventMap.cs:line 109
   at Roslyn.Utilities.EventMap.EventHandlerSet`1.RaiseEvent[TArg](Action`2 invoker, TArg arg) in /_/src/Workspaces/SharedUtilitiesAndExtensions/Compiler/Core/Utilities/EventMap.cs:line 170
   at Microsoft.CodeAnalysis.Workspace.OnWorkspaceFailed(WorkspaceDiagnostic diagnostic) in /_/src/Workspaces/Core/Portable/Workspace/Workspace_Events.cs:line 103
   at Microsoft.CodeAnalysis.MSBuild.MSBuildWorkspace.OnWorkspaceFailed(WorkspaceDiagnostic diagnostic) in /_/src/Workspaces/MSBuild/Core/MSBuild/MSBuildWorkspace.cs:line 110
   at Microsoft.CodeAnalysis.MSBuild.DiagnosticReporter.Report(WorkspaceDiagnostic diagnostic) in /_/src/Workspaces/MSBuild/Core/MSBuild/DiagnosticReporter.cs:line 54
   at Microsoft.CodeAnalysis.MSBuild.DiagnosticReporterLoggerProvider.Logger.Log[TState](LogLevel logLevel, EventId eventId, TState state, Exception exception, Func`3 formatter) in /_/src/Workspaces/MSBuild/Core/MSBuild/DiagnosticReporterLoggerProvider.cs:line 59

The stack here is a bit confusing to diagnose, so here's the series of events:

1. We are trying to shut down the BuildHost process. While we are calling Dispose on the BuildHostProcess here:

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

Line 162 in 40ec700

await process.DisposeAsync().ConfigureAwait(false);

2. This causes us to call into the build host to tell it to shut down here:

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

Lines 428 to 448 in 40ec700

	try
	{
	if (!_process.HasExited)
	{
	_logger?.LogTrace("Sending a Shutdown request to the BuildHost.");
	await BuildHost.ShutdownAsync(CancellationToken.None).ConfigureAwait(false);
	}
	_rpcClient.Shutdown();
	_logger?.LogTrace("Process shut down.");
	}
	catch (Exception e)
	{
	_logger?.LogError(e, "Exception while shutting down the BuildHost process.");
	// Process may have gone bad, so not much else we can do.
	LogProcessFailure();
	_process.Kill();
	}

3. That call to the build host threw a "Pipe is broken" IO exception.
4. That exception was caught, and the _logger?.LogError() above runs.
5. The logger we create in MSBuildWorkspace raises this as a WorkspaceFailed event.
6. The unit tests hook WorkspaceFailed, and throw an exception here:

roslyn/src/Workspaces/MSBuild/Test/MSBuildWorkspaceTestBase.cs

Line 154 in 5bbda37

workspace.WorkspaceFailed += (s, e) => throw new Exception($"Workspace failure {e.Diagnostic.Kind}:{e.Diagnostic.Message}");

7. Microsoft.Extensions.Logging then catches that exception and throws a new exception saying an error occurred while writing to the logger, with the Exception thrown in WorkspaceFailed being the inner exception.

It's unclear from me if something caused the pipe to break first, or simply the other process is shutting down and we're converting a failure in that case that's expected to something that's unexpected. We could replace that LogError with a LogTrace or something that won't raise WorkspaceFailed, but that might be masking the root cause here.

[jasonmalinowski]

@dibarbet @JoeRobich Any chance we recently added something to the MSBuildWorkspace tests to have it capture the full ILogger log of MSBuildWorkspace? That might be helpful in this case.

[dibarbet]

@dibarbet @JoeRobich Any chance we recently added something to the MSBuildWorkspace tests to have it capture the full ILogger log of MSBuildWorkspace? That might be helpful in this case.

@jasonmalinowski not as far as I know - my recommendation would be to create one that uses the xunit logger (we do that in LSP tests - https://github.com/dotnet/roslyn/blob/main/src/EditorFeatures/TestUtilities/LanguageServer/TestOutputLspLogger.cs#L14)

[jasonmalinowski]

PR to do use exactly that code (after some refactoring): #77072