Intermittent error "Could not find build environment" #125

duncanawoods · 2020-02-04T15:50:30Z

I am seeing intermittent failures of GetWorkspace. The frequency seems proportional to the number of projects in a solution:

5 projects and it doesn't happen
10 projects and it's 50% of the time
13 projects and it always happens.

Given the parallelization in the stack trace, it might be relevant that I am on a 12 core machine.

Example test

[Test]
public void test()
{
    var manager = new AnalyzerManager("Test.sln");
    var workspace = manager.GetWorkspace();
}

Versions

Buildalyzer: 2.5.0
Buildalyzer.Workspaces: 2.5.0
dotnet: 3.1.101
OS: ubuntu 18.04

Exception trace:

System.AggregateException : One or more errors occurred. (One or more errors occurred. (Could not find build environment)) (Could not find build environment)
  ----> System.InvalidOperationException : Could not find build environment
   at System.Linq.Parallel.QueryTaskGroupState.QueryEnd(Boolean userInitiatedDispose)
   at System.Linq.Parallel.SpoolingTask.SpoolStopAndGo[TInputOutput,TIgnoreKey](QueryTaskGroupState groupState, PartitionedStream`2 partitions, SynchronousChannel`1[] channels, TaskScheduler taskScheduler)
   at System.Linq.Parallel.DefaultMergeHelper`2.System.Linq.Parallel.IMergeHelper<TInputOutput>.Execute()
   at System.Linq.Parallel.MergeExecutor`1.Execute()
   at System.Linq.Parallel.MergeExecutor`1.Execute[TKey](PartitionedStream`2 partitions, Boolean ignoreOutput, ParallelMergeOptions options, TaskScheduler taskScheduler, Boolean isOrdered, CancellationState cancellationState, Int32 queryId)
   at System.Linq.Parallel.PartitionedStreamMerger`1.Receive[TKey](PartitionedStream`2 partitionedStream)
   at System.Linq.Parallel.WhereQueryOperator`1.WrapPartitionedStream[TKey](PartitionedStream`2 inputStream, IPartitionedStreamRecipient`1 recipient, Boolean preferStriping, QuerySettings settings)
   at System.Linq.Parallel.UnaryQueryOperator`2.UnaryQueryOperatorResults.ChildResultsRecipient.Receive[TKey](PartitionedStream`2 inputStream)
   at System.Linq.Parallel.UnaryQueryOperator`2.UnaryQueryOperatorResults.GivePartitionedStream(IPartitionedStreamRecipient`1 recipient)
   at System.Linq.Parallel.UnaryQueryOperator`2.UnaryQueryOperatorResults.GivePartitionedStream(IPartitionedStreamRecipient`1 recipient)
   at System.Linq.Parallel.QueryOperator`1.GetOpenedEnumerator(Nullable`1 mergeOptions, Boolean suppressOrder, Boolean forEffect, QuerySettings querySettings)
   at System.Linq.Parallel.QueryOpeningEnumerator`1.OpenQuery()
   at System.Linq.Parallel.QueryOpeningEnumerator`1.MoveNext()
   at System.Linq.ParallelEnumerable.ToList[TSource](ParallelQuery`1 source)
   at Buildalyzer.Workspaces.AnalyzerManagerExtensions.GetWorkspace(AnalyzerManager manager)
   at CallGraphTest.TestParsing.test() in /home/duncan/Projects/snug/tools/CallGraph/CallGraphTest/TestParsing.cs:line 260
   at NUnit.Framework.Internal.TaskAwaitAdapter.GenericAdapter`1.GetResult()
   at NUnit.Framework.Internal.AsyncToSyncAdapter.Await(Func`1 invoke)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.RunTestMethod(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.Execute(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.BeforeAndAfterTestCommand.<>c__DisplayClass1_0.<Execute>b__0()
   at NUnit.Framework.Internal.Commands.BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)
--InvalidOperationException
   at Buildalyzer.Environment.EnvironmentFactory.GetBuildEnvironment(String targetFramework, EnvironmentOptions options)
   at Buildalyzer.Environment.EnvironmentFactory.GetBuildEnvironment(String targetFramework)
   at Buildalyzer.ProjectAnalyzer.Build(String targetFramework)
   at Buildalyzer.ProjectAnalyzer.Build()
   at Buildalyzer.Workspaces.AnalyzerManagerExtensions.<>c.<GetWorkspace>b__0_0(ProjectAnalyzer p)
   at System.Linq.Parallel.SelectQueryOperator`2.SelectQueryOperatorResults.GetElement(Int32 index)
   at System.Linq.Parallel.QueryResults`1.get_Item(Int32 index)
   at System.Linq.Parallel.PartitionedDataSource`1.ListContiguousIndexRangeEnumerator.MoveNext(T& currentElement, Int32& currentKey)
   at System.Linq.Parallel.WhereQueryOperator`1.WhereQueryOperatorEnumerator`1.MoveNext(TInputOutput& currentElement, TKey& currentKey)
   at System.Linq.Parallel.StopAndGoSpoolingTask`2.SpoolingWork()
   at System.Linq.Parallel.SpoolingTaskBase.Work()
   at System.Linq.Parallel.QueryTask.BaseWork(Object unused)
   at System.Linq.Parallel.QueryTask.<>c.<.cctor>b__10_0(Object o)
   at System.Threading.Tasks.Task.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)

The text was updated successfully, but these errors were encountered:

daveaglick · 2020-02-05T01:38:20Z

Thanks for the report. The error “Could not find build environment” typically happens in a couple specific cases:

A project does not use the SDK and it can’t figure out where to find the .NET Framework version of MSBuild
A project uses the SDK and we can’t get a parseable response from dotnet --info

The fact this is only happening intermittently though is interesting. Any idea if it’s always the same project that triggers the error? One thing I could do is make that clearer: “could not find build environment for someproject.csproj”.

Are all the projects in the solution .NET Core or are there a mix of projects? It’s possible trying to make a bunch of dotnet --info call’s one parallel could be failing.

duncanawoods · 2020-02-06T12:10:39Z

Any idea if it’s always the same project that triggers the error?

No idea I'm afraid. I was actually removing projects expecting to find one of them was the cause but instead I just found a point where it worked intermittently.

One thing I could do is make that clearer: “could not find build environment for someproject.csproj”.

I'll try and do that today.

Are all the projects in the solution .NET Core

Yes they are all .net core. The only unusual things that I will test today:

one of the projects has to specify two frameworks because of the aspnet core / .netstandard incompatibility that was added in 3.1 <TargetFrameworks>netstandard2.0;netcoreapp3.1</TargetFrameworks>
the solution was open in jetbrains rider - possible interference maybe?

daveaglick · 2020-02-06T13:00:40Z

Great - thanks for following up. Let me know what you find. Both your thoughts about multi-targeting and Rider sounds plausible - or could be something totally different. To good news is that the problem does seem to be happening at the dotnet --info stage which should help narrow it down. I'll sit tight until you report back and then I'll see if I can replicate if you don't pin it down.

duncanawoods · 2020-02-06T15:42:07Z

Quick note; I tried running with latest head and also the 2.5 version but I get a run-time exception about MsBuildPipeLogger. Removing the packing shenanigans in Buildalyzer.Logger.csproj let me run.

Unhandled exception. One or more errors occurred. (One or more errors occurred. (Could not load file or assembly 'MsBuildPipeLogger.Logger, Version=1.1.2.0, Culture=neutral, PublicKeyToken=null'. The system cannot find the file specified.
)) (Could not load file or assembly 'MsBuildPipeLogger.Logger, Version=1.1.2.0, Culture=neutral, PublicKeyToken=null'. The system cannot find the file specified.
)
System.AggregateException: One or more errors occurred. (Safe handle has been closed.
Object name: 'SafeHandle'.)
 ---> System.ObjectDisposedException: Safe handle has been closed.
Object name: 'SafeHandle'.
   at System.Runtime.InteropServices.SafeHandle.DangerousAddRef(Boolean& success)
   at System.StubHelpers.StubHelpers.SafeHandleAddRef(SafeHandle pHandle, Boolean& success)
   at Interop.Sys.Read(SafePipeHandle fd, Byte* buffer, Int32 count)
   at System.IO.Pipes.PipeStream.ReadCore(Span`1 buffer)
   at System.IO.Pipes.PipeStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Stream.<>c.<BeginReadInternal>b__43_0(Object <p0>)
   at System.Threading.Tasks.Task`1.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__274_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location where exception was thrown ---
   at System.IO.Stream.EndRead(IAsyncResult asyncResult)
   at System.IO.Pipes.PipeStream.EndRead(IAsyncResult asyncResult)
   at System.IO.Stream.<>c.<BeginEndReadAsync>b__48_1(Stream stream, IAsyncResult asyncResult)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncTrimPromise`1.Complete(TInstance thisRef, Func`3 endMethod, IAsyncResult asyncResult, Boolean requiresSynchronization)
   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Wait(CancellationToken cancellationToken)
   at MsBuildPipeLogger.PipeBuffer.Buffer.<>c__DisplayClass11_0.<FillFromStream>b__0()
   at MsBuildPipeLogger.CancellationTokenExtensions.Try[TResult](CancellationToken cancellationToken, Func`1 action, Func`1 cancelled)
   at MsBuildPipeLogger.PipeBuffer.Buffer.FillFromStream(Stream stream, CancellationToken cancellationToken)
   at MsBuildPipeLogger.PipeBuffer.FillFromStream(Stream stream, CancellationToken cancellationToken)
   at MsBuildPipeLogger.AnonymousPipeLoggerServer.Connect()
   at MsBuildPipeLogger.PipeLoggerServer`1.<.ctor>b__12_0()
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
   at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadHelper.ThreadStart()

duncanawoods · 2020-02-06T15:46:51Z

Info so far:

it's definitely not happening on the same project
on a 15 project solution, I typically get 3 projects failing (sometimes only 1) but a different three each time
happens without the solution open in rider

duncanawoods · 2020-02-06T16:51:19Z

The cause is a race condition between the Process.Exited and Process.OutputDataReceived events. This results in ProcessRunner.Output.Count == 0 causing the failure despite the process successfully completing because the stdout hasn't been appended yet.

I tried adding some synchronisation around the ProcessRunner.Output in OutputDataReceived but it still didn't resolve the race condition because I believe that exit is signalled before the OutputDataReceived is even called.

The solution is kind of insane. See the remarks at the bottom of here for the problem:

https://docs.microsoft.com/en-us/dotnet/api/system.diagnostics.process.waitforexit?redirectedfrom=MSDN&view=netcore-3.1#System_Diagnostics_Process_WaitForExit_System_Int32

When standard output has been redirected to asynchronous event handlers, it is possible that output processing will not have completed when this method returns. To ensure that asynchronous event handling has been completed, call the WaitForExit() overload that takes no parameter after receiving a true from this overload.

So the fix is to change ProcessRunner.WaitForExit(int timeout) from:

public bool WaitForExit(int timeout) => Process.WaitForExit(timeout);

to

public bool WaitForExit(int timeout)
{
    bool result = Process.WaitForExit(timeout);

    Process.WaitForExit();

    return result;
}

I can confirm this works.

daveaglick · 2020-02-13T20:47:02Z

Lol. That's...goofy. Thanks a bunch for running this to ground! Making the change now and will release momentarily.

daveaglick · 2020-02-13T20:48:52Z

I think I probably have a lot of projects that need to be patched now :)

duncanawoods · 2020-02-13T20:56:48Z

Thanks @daveaglick much appreciated!

daveaglick · 2020-02-13T21:00:54Z

2.5.1 rolling out now, should show up in NuGet in about 10 minutes (unless NuGet is slow indexing, which happens often)

daveaglick added the ⚠ Bug Something isn't working as expected label Feb 5, 2020

duncanawoods mentioned this issue Feb 6, 2020

Intermittent: Empty Process stdout dotnet/runtime#27128

Open

daveaglick added a commit that referenced this issue Feb 13, 2020

Fixes a nasty Process.WaitForExit() race condition (#125)

a9806c8

daveaglick added a commit that referenced this issue Feb 13, 2020

Fixes a nasty Process.WaitForExit() race condition (#125)

7723232

daveaglick closed this as completed Feb 13, 2020

lostmsu mentioned this issue Mar 24, 2021

Intermittent error "Could not find build environment" #174

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Intermittent error "Could not find build environment" #125

Intermittent error "Could not find build environment" #125

duncanawoods commented Feb 4, 2020

daveaglick commented Feb 5, 2020

duncanawoods commented Feb 6, 2020

daveaglick commented Feb 6, 2020

duncanawoods commented Feb 6, 2020 •

edited

Loading

duncanawoods commented Feb 6, 2020 •

edited

Loading

duncanawoods commented Feb 6, 2020 •

edited

Loading

daveaglick commented Feb 13, 2020

daveaglick commented Feb 13, 2020

duncanawoods commented Feb 13, 2020

daveaglick commented Feb 13, 2020

Intermittent error "Could not find build environment" #125

Intermittent error "Could not find build environment" #125

Comments

duncanawoods commented Feb 4, 2020

Example test

Versions

Exception trace:

daveaglick commented Feb 5, 2020

duncanawoods commented Feb 6, 2020

daveaglick commented Feb 6, 2020

duncanawoods commented Feb 6, 2020 • edited Loading

duncanawoods commented Feb 6, 2020 • edited Loading

duncanawoods commented Feb 6, 2020 • edited Loading

daveaglick commented Feb 13, 2020

daveaglick commented Feb 13, 2020

duncanawoods commented Feb 13, 2020

daveaglick commented Feb 13, 2020

duncanawoods commented Feb 6, 2020 •

edited

Loading

duncanawoods commented Feb 6, 2020 •

edited

Loading

duncanawoods commented Feb 6, 2020 •

edited

Loading