You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
I've attempted to run a multi-node build of a solution (about 15 projects, mix of C# "classic" and F# "SDK" style, all library and desktop executables, with some dependencies on each other), and it failed quite miserably. Essentially, I am modifying the sample's Bulder class. The resolution of DLLS in the controlling process happens just fine, but then it launches a load of nodes (500+ node processes!) it cannot communitcate with. Debugging it (and I even pulled the whole MSBuild and stepped through some code), I cannot understand how that could be possible!
This is Windows 10, net46 build target.
Now my Build method looks like this:
publicboolBuild(stringslnFile){//var sln = SolutionFile.Parse(slnFile);varprops=newDictionary<string,string>(){{"Configuration","Release"},{"Platform","Mixed Platforms"}};vartargets=new[]{"Rebuild"};varcpuCount=8;// Change to 1, works like a charm...varpcoll=newProjectCollection(props,null,null,ToolsetDefinitionLocations.Default,cpuCount,false);varbparam=newBuildParameters(pcoll);//bparam.Loggers = new[] { new Logger() };bparam.EnableNodeReuse=true;bparam.UseSynchronousLogging=true;bparam.MaxNodeCount=cpuCount;// Environment.ProcessorCount = 8, HT off here;BuildManager.DefaultBuildManager.BeginBuild(bparam);varbreqdata=newBuildRequestData(slnFile,props,null,targets,null);varbreq=BuildManager.DefaultBuildManager.PendBuildRequest(breqdata);varbresult=breq.Execute();if(bresult.OverallResult==BuildResultCode.Success)Console.WriteLine("Success.");elseConsole.WriteLine($"Failure: {bresult.Exception}");returnbresult.OverallResult==BuildResultCode.Success;}
(I noticed XBuild.cs sets up a distributed logger; I tried disconnecting the logger at all, but nothing changed).
Printed version and locations from typeof(Project) in Build..ctor() -- I moved it there:
BuildApp running using MSBuild version 15.9.20.62856
C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin
What happens is the build progresses very slowly, and the same project is the solution is reported to be build multiple times, according to the log, with the modified logger from the sample, going like
Then, after ~55s, with the whole machine slowed down to a crawl (and it's a decent 8 Core-X CPU, 64GB workstation), the build ends up in an exception:
Failure: Microsoft.Build.Exceptions.BuildAbortedException: Build was canceled. Failed to successfully launch or connect to a child MSBuild.exe process. Verify that the MSBuild.exe "C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe" launches successfully, and that it is loading the same microsoft.build.dll that the launching process loaded. If the location seems incorrect, try specifying the correct location in the BuildParameters object, or with the MSBUILD_EXE_PATH environment variable.
at Microsoft.Build.BackEnd.NodeProviderOutOfProc.CreateNode(Int32 nodeId, INodePacketFactory factory, NodeConfiguration configuration)
at Microsoft.Build.BackEnd.NodeManager.AttemptCreateNode(INodeProvider nodeProvider, NodeConfiguration nodeConfiguration)
at Microsoft.Build.BackEnd.NodeManager.CreateNode(NodeConfiguration configuration, NodeAffinity nodeAffinity)
at Microsoft.Build.Execution.BuildManager.PerformSchedulingActions(IEnumerable`1 responses)
at Microsoft.Build.Execution.BuildManager.ProcessPacket(Int32 node, INodePacket packet)
at Microsoft.Build.Execution.BuildManager.ProcessWorkQueue(Action action)
That's a good hint, actually! When I examined the node processes with the Process Explorer, I learned that the nodes load the 4.0 ngen'd DLLs from the GAC:
Microsoft.Build.Framework.ni.dll Microsoft.Build.Framework.dll C:\Windows\assembly\NativeImages_v4.0.30319_32\Microsoft.B3325a29b#\5a6bce706c5ad1680b4ab0929f335bea\Microsoft.Build.Framework.ni.dll
Microsoft.Build.ni.dll Microsoft.Build.dll C:\Windows\assembly\NativeImages_v4.0.30319_32\Microsoft.Build\2ab27b3a8ecfb41bed7ff1f9babbefaa\Microsoft.Build.ni.dll
MSBuild.exe MSBuild.exe C:\Program Files (x86)\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
MSBuild.ni.exe MSBuild.exe C:\Windows\assembly\NativeImages_v4.0.30319_32\MSBuild\de9f9e05d8cfda95db18a2becab787ea\MSBuild.ni.exe
mscoree.dll Microsoft .NET Runtime... C:\Windows\SysWOW64\mscoree.dll
mscoreei.dll Microsoft .NET Runtime... C:\Windows\Microsoft.NET\Framework\v4.0.30319\mscoreei.dll
mscorlib.ni.dll Microsoft Common Langu... C:\Windows\assembly\NativeImages_v4.0.30319_32\mscorlib\31202f32d626603baaac9a296830c313\mscorlib.ni.dll
while my main process is resolving the correct DLLs. I have only one MSBuild installation, one from the VS15.9.2 payload; it is discovered correctly and all assemblies load into my process from it:
After some digging through MSBuild source, and figuring out how the nodes are started, I am seriously baffled. I've enable the comm logging
set MSBUILDDEBUGCOMM=1
set MSBUILDDEBUGPATH=C:\projects\msbuildIntegrated\commtrace
and got a directory of 581 files, one of these not like the others, corresponding to my process PID. The node-produced logs all indeed are waiting for communication, rejecting a request from the wrong M.Build.dll
OutOfProc Endpoint Packet Pump (TID 4) 636786595802303341 + 1.0028ms: Waiting for connection 900000 ms...
OutOfProc Endpoint Packet Pump (TID 4) 636786595802313312 + 0.9971ms: Parent started connecting. Reading handshake from parent
OutOfProc Endpoint Packet Pump (TID 4) 636786595802353309 + 3.9997ms: Handshake failed. Received 67324607693914107 from host not 67324607693914090. Probably the host is a different MSBuild build.
OutOfProc Endpoint Packet Pump (TID 4) 636786595802353309 + 0ms: Waiting for connection 899995 ms...
OutOfProc Endpoint Packet Pump (TID 4) 636786604802204420 + 899985.1ms: Connection timed out waiting a host to contact us. Exiting comm thread.
OutOfProc Endpoint Packet Pump (TID 4) 636786604802214432 + 1.0012ms: Changing link status from Inactive to ConnectionFailed
(TID 1) 636786604802234442 + 2.001ms: Changing link status from ConnectionFailed to Inactive
and the driver launches nodes and is unable to communicate to them
(TID 4) 636786595470837289 + 1.9995ms: Starting to acquire a new or existing node to establish node ID 2...
(TID 4) 636786595470917290 + 8.0001ms: Attempting to connect to each existing msbuild.exe process in turn to establish node 2...
(TID 4) 636786595470927297 + 1.0007ms: Could not connect to existing process, now creating a process...
(TID 4) 636786595470957291 + 2.9994ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595470997289 + 3.9998ms: Successfully launched msbuild.exe node with PID 20036
(TID 4) 636786595471017291 + 2.0002ms: Attempting connect to PID 20036 with pipe MSBuild20036 with timeout 30000 ms
(TID 4) 636786595471737279 + 71.9988ms: Writing handshake to pipe MSBuild20036
(TID 4) 636786595471747282 + 1.0003ms: Reading handshake from pipe MSBuild20036
(TID 4) 636786595471797283 + 5.0001ms: Failed to connect to pipe MSBuild20036. Unexpected end of stream while reading for handshake
(TID 4) 636786595471807298 + 1.0015ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595471837290 + 2.9992ms: Successfully launched msbuild.exe node with PID 46316
(TID 4) 636786595471847309 + 1.0019ms: Attempting connect to PID 46316 with pipe MSBuild46316 with timeout 30000 ms
(TID 4) 636786595472537298 + 68.9989ms: Writing handshake to pipe MSBuild46316
(TID 4) 636786595472547279 + 0.9981ms: Reading handshake from pipe MSBuild46316
(TID 4) 636786595472587268 + 3.9989ms: Failed to connect to pipe MSBuild46316. Unexpected end of stream while reading for handshake
(TID 4) 636786595472597298 + 1.003ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595472637274 + 3.9976ms: Successfully launched msbuild.exe node with PID 72032
(TID 4) 636786595472827271 + 18.9997ms: Attempting connect to PID 72032 with pipe MSBuild72032 with timeout 30000 ms
(TID 4) 636786595473337288 + 51.0017ms: Writing handshake to pipe MSBuild72032
(TID 4) 636786595473347260 + 0.9972ms: Reading handshake from pipe MSBuild72032
(TID 4) 636786595473407264 + 6.0004ms: Failed to connect to pipe MSBuild72032. Unexpected end of stream while reading for handshake
(TID 4) 636786595473417286 + 1.0022ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595473457293 + 4.0007ms: Successfully launched msbuild.exe node with PID 18344
(TID 4) 636786595473457293 + 0ms: Attempting connect to PID 18344 with pipe MSBuild18344 with timeout 30000 ms
(TID 4) 636786595474087250 + 62.9957ms: Writing handshake to pipe MSBuild18344
(TID 4) 636786595474097251 + 1.0001ms: Reading handshake from pipe MSBuild18344
(TID 4) 636786595474147267 + 5.0016ms: Failed to connect to pipe MSBuild18344. Unexpected end of stream while reading for handshake
(TID 4) 636786595474157272 + 1.0005ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595474187248 + 2.9976ms: Successfully launched msbuild.exe node with PID 47460
(TID 4) 636786595474197262 + 1.0014ms: Attempting connect to PID 47460 with pipe MSBuild47460 with timeout 30000 ms
(TID 4) 636786595474827268 + 63.0006ms: Writing handshake to pipe MSBuild47460
(TID 4) 636786595474837254 + 0.9986ms: Reading handshake from pipe MSBuild47460
(TID 4) 636786595474877240 + 3.9986ms: Failed to connect to pipe MSBuild47460. Unexpected end of stream while reading for handshake
(TID 4) 636786595474887270 + 1.003ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595474917248 + 2.9978ms: Successfully launched msbuild.exe node with PID 45588
(TID 4) 636786595474917248 + 0ms: Attempting connect to PID 45588 with pipe MSBuild45588 with timeout 30000 ms
(TID 4) 636786595475567236 + 64.9988ms: Writing handshake to pipe MSBuild45588
(TID 4) 636786595475577237 + 1.0001ms: Reading handshake from pipe MSBuild45588
(TID 4) 636786595475617248 + 4.0011ms: Failed to connect to pipe MSBuild45588. Unexpected end of stream while reading for handshake
(TID 4) 636786595475627258 + 1.001ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595475657228 + 2.997ms: Successfully launched msbuild.exe node with PID 22864
(TID 4) 636786595475667224 + 0.9996ms: Attempting connect to PID 22864 with pipe MSBuild22864 with timeout 30000 ms
(TID 4) 636786595476277235 + 61.0011ms: Writing handshake to pipe MSBuild22864
(TID 4) 636786595476287219 + 0.9984ms: Reading handshake from pipe MSBuild22864
(TID 4) 636786595476337232 + 5.0013ms: Failed to connect to pipe MSBuild22864. Unexpected end of stream while reading for handshake
(TID 4) 636786595476337232 + 0ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595476377226 + 3.9994ms: Successfully launched msbuild.exe node with PID 27756
(TID 4) 636786595476377226 + 0ms: Attempting connect to PID 27756 with pipe MSBuild27756 with timeout 30000 ms
(TID 4) 636786595477007212 + 62.9986ms: Writing handshake to pipe MSBuild27756
(TID 4) 636786595477017249 + 1.0037ms: Reading handshake from pipe MSBuild27756
(TID 4) 636786595477087214 + 6.9965ms: Failed to connect to pipe MSBuild27756. Unexpected end of stream while reading for handshake
(TID 4) 636786595477097217 + 1.0003ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595477137222 + 4.0005ms: Successfully launched msbuild.exe node with PID 97684
(TID 4) 636786595477137222 + 0ms: Attempting connect to PID 97684 with pipe MSBuild97684 with timeout 30000 ms
(TID 4) 636786595477767209 + 62.9987ms: Writing handshake to pipe MSBuild97684
(TID 4) 636786595477777207 + 0.9998ms: Reading handshake from pipe MSBuild97684
(TID 4) 636786595477827218 + 5.0011ms: Failed to connect to pipe MSBuild97684. Unexpected end of stream while reading for handshake
(TID 4) 636786595477837216 + 0.9998ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
(TID 4) 636786595477867201 + 2.9985ms: Successfully launched msbuild.exe node with PID 81016
(TID 4) 636786595477877203 + 1.0002ms: Attempting connect to PID 81016 with pipe MSBuild81016 with timeout 30000 ms
(TID 4) 636786595478487235 + 61.0032ms: Writing handshake to pipe MSBuild81016
(TID 4) 636786595478497200 + 0.9965ms: Reading handshake from pipe MSBuild81016
(TID 4) 636786595478537192 + 3.9992ms: Failed to connect to pipe MSBuild81016. Unexpected end of stream while reading for handshake
(TID 4) 636786595478547198 + 1.0006ms: FAILED TO CONNECT TO A CHILD NODE
(TID 30) 636786595492597024 + 1404.983ms: Starting to acquire a new or existing node to establish node ID 3...
(TID 30) 636786595492647021 + 4.9997ms: Attempting to connect to each existing msbuild.exe process in turn to establish node 3...
(TID 30) 636786595492657020 + 0.9999ms: Could not connect to existing process, now creating a process...
(TID 30) 636786595492667016 + 0.9996ms: Launching node from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
...
This repeats over and over. Maybe the only notable change is the TID changes from time to time (4 different TIDs are logging, one strictly after the other).
Looking at the process launch code, I am at a loss. The processes are launched with the off-the-shelf native Win32 ::CreateProcess() call. MSBuild.exe.config is perfectly normal, and msbuld works from the dev console just fine. How is it possible MSBuild.exe nodes do not see their manifest? I cannot explain, something very tricky is going on!
The only thing notable about my setup is I have a directory junction, among others, C:\_PX\ -> C:\Program Files (x86); I came to use that setup since Vista times, that (and Windows 7 too) ran out of env space with long paths. For the same reason, I shorten Microsoft Visual Studio to MSVS when first set it up. This is why the paths may vary. (Aside, cmd's env space does not appear to be a problem in Windows 10 any more, but... just in case). This set up has never caused me a problem with any program whatsoever, VS with additional (Intel) C++ compilers, msbuild or multiple other packages, MATLAB, Mathematica, a few Pythons and data sci packages, you name it. Otherwise, everything is perfectly non-hacksy.
and I swear I did not touch msbuild.exe.config, which has redirects to the same 15.1.0.0 for all DLLs. Besides, it works from command line, or when I launch the process from command line, or from my build tool (that I wanted to replace with the Locator and API calls, but oops).
If there is anything I can do more to trace the issue, please let me know. I am entirely out of ideas. The Locator's handler, even if active, should not affect the nodes launched with a native Win32 API in any way, I believe. So the longer I am looking at the whole issue, the more "it can't happen!" it looks to me. Help!
Adding more info. I captured the Fusion logs, and they are... interesting. Here is MsBuild.exe binding M.Build.dll.
Note added after adding more info: This may or may not be a red herring, as I ran another, normal command line build with the same arguments, carefully wiping all fusion logs and killing nodes between tests and the log entries look exactly same. I think I should stop experimenting with it, or my brain would boil and evaporate. So msbuild.exe 15.0 loads msbuild.ni.exe 4.0 and Microsoft.Build.ni.dll 4.0 from the GAC as its business as usual. Scares last remaining bejeebers out of me.
The "Default" log looks quite normal, and consists all of the same short repeating entry
Fusion log entries
*** Assembly Binder Log Entry (18-11-24 @ 21:05:40) ***
The operation was successful.
Bind result: hr = 0x0. The operation completed successfully.
Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Running under executable C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
--- A detailed error log follows.
=== Pre-bind state information ===
LOG: DisplayName = Microsoft.Build, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
(Fully-specified)
LOG: Appbase = file:///C:/_PX/MSVS/2017/Enterprise/MSBuild/15.0/Bin/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = MSBuild.exe
Calling assembly : MSBuild, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
===
LOG: This bind starts in default load context.
LOG: Using application configuration file: C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe.Config
LOG: Using host configuration file:
LOG: Using machine configuration file from C:\Windows\Microsoft.NET\Framework\v4.0.30319\config\machine.config.
LOG: Redirect found in application configuration file: 15.1.0.0 redirected to 15.1.0.0.
LOG: Post-policy reference: Microsoft.Build, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
LOG: Binding succeeds. Returns assembly from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.dll.
LOG: Assembly is loaded in default load context.
Native image log entries are strange, and I cannot make sense of them. The same group of 4 entries repeats over and over, and in the end it looks like it happily binds to the GAC version of the 4.0.0.0 assembly.
*** Assembly Binder Log Entry (18-11-24 @ 21:05:29) ***
The operation was successful.
Bind result: hr = 0x0. The operation completed successfully.
Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Running under executable C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
--- A detailed error log follows.
=== Pre-bind state information ===
LOG: DisplayName = Microsoft.Build, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
(Fully-specified)
LOG: Appbase = file:///C:/_PX/MSVS/2017/Enterprise/MSBuild/15.0/Bin/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = MSBuild.exe
Calling assembly : (Unknown).
===
LOG: IL assembly loaded from C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\Microsoft.Build.dll.
*** Assembly Binder Log Entry (18-11-24 @ 21:05:29) ***
The operation was successful.
Bind result: hr = 0x0. The operation completed successfully.
Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Running under executable C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
--- A detailed error log follows.
BEGIN : Native image bind.
LOG: Start validating all the dependencies.
LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
LOG: [Level 1]Start validating IL dependency Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating native image dependency System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
LOG: [Level 1]Start validating native image dependency System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
LOG: [Level 1]Start validating IL dependency System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Runtime, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Runtime, Version=4.0.20.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
LOG: [Level 1]Start validating IL dependency System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089, processorArchitecture=MSIL
LOG: Start validating all the dependencies.
LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
LOG: [Level 1]Start validating IL dependency Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating native image dependency System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
LOG: [Level 1]Start validating native image dependency System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
LOG: [Level 1]Start validating IL dependency System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Runtime, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Runtime, Version=4.0.20.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
LOG: [Level 1]Start validating IL dependency System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089, processorArchitecture=MSIL
WRN: Timestamp of the IL assembly does not match record in .aux file. Loading IL to compare signature.
LOG: [Level 1]Start validating IL dependency System.Threading.Tasks.Dataflow, Version=4.5.24.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Threading.Tasks.Dataflow, Version=4.5.24.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Runtime.Serialization, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
Dependency name: System.Runtime.Serialization, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Threading.Tasks, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Threading.Tasks, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Runtime.InteropServices.RuntimeInformation, Version=4.0.1.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Runtime.InteropServices.RuntimeInformation, Version=4.0.1.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a, processorArchitecture=MSIL
LOG: [Level 1]Start validating IL dependency System.Collections, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Collections, Version=4.0.10.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
LOG: [Level 1]Start validating IL dependency System.Runtime.Extensions, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Dependency name: System.Runtime.Extensions, Version=4.0.10.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
LOG: Validation of dependencies succeeded.
END : The operation completed successfully. (Exception from HRESULT: 0x00000000 (S_OK))
*** Assembly Binder Log Entry (18-11-24 @ 21:05:29) ***
The operation was successful.
Bind result: hr = 0x0. The operation completed successfully.
Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Running under executable C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
--- A detailed error log follows.
=== Pre-bind state information ===
LOG: DisplayName = Microsoft.Build, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
(Fully-specified)
LOG: Appbase = file:///C:/_PX/MSVS/2017/Enterprise/MSBuild/15.0/Bin/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = MSBuild.exe
Calling assembly : MSBuild, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
===
LOG: Start validating all the dependencies.
LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating native image dependency System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating native image dependency System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: Start validating all the dependencies.
LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating native image dependency System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating native image dependency System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
WRN: Timestamp of the IL assembly does not match record in .aux file. Loading IL to compare signature.
LOG: [Level 1]Start validating IL dependency System.Threading.Tasks.Dataflow, Version=4.5.24.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime.Serialization, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Threading.Tasks, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime.InteropServices.RuntimeInformation, Version=4.0.1.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Collections, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime.Extensions, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Native image has correct version information.
LOG: Validation of dependencies succeeded.
LOG: Bind to native image succeeded.
*** Assembly Binder Log Entry (18-11-24 @ 21:05:29) ***
The operation was successful.
Bind result: hr = 0x0. The operation completed successfully.
Assembly manager loaded from: C:\Windows\Microsoft.NET\Framework\v4.0.30319\clr.dll
Running under executable C:\_PX\MSVS\2017\Enterprise\MSBuild\15.0\Bin\MSBuild.exe
--- A detailed error log follows.
=== Pre-bind state information ===
LOG: DisplayName = Microsoft.Build, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a
(Fully-specified)
LOG: Appbase = file:///C:/_PX/MSVS/2017/Enterprise/MSBuild/15.0/Bin/
LOG: Initial PrivatePath = NULL
LOG: Dynamic Base = NULL
LOG: Cache Base = NULL
LOG: AppName = MSBuild.exe
Calling assembly : MSBuild, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
===
LOG: Start validating all the dependencies.
LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating native image dependency System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating native image dependency System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: Start validating all the dependencies.
LOG: [Level 1]Start validating native image dependency mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency Microsoft.Build.Framework, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating native image dependency System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating native image dependency System.Core, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Configuration, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Xml, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Collections.Immutable, Version=1.2.3.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.IO.Compression, Version=4.1.2.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
WRN: Timestamp of the IL assembly does not match record in .aux file. Loading IL to compare signature.
LOG: [Level 1]Start validating IL dependency System.Threading.Tasks.Dataflow, Version=4.5.24.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime.Serialization, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089.
LOG: [Level 1]Start validating IL dependency System.Threading.Tasks, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime.InteropServices.RuntimeInformation, Version=4.0.1.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Collections, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
LOG: [Level 1]Start validating IL dependency System.Runtime.Extensions, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a.
Native image has correct version information.
LOG: Validation of dependencies succeeded.
LOG: Bind to native image succeeded.
Attempting to use native image C:\WINDOWS\assembly\NativeImages_v4.0.30319_32\Microsoft.Build\2ab27b3a8ecfb41bed7ff1f9babbefaa\Microsoft.Build.ni.dll.
Native image successfully used.
Baffling. I have not a trace of an idea what to make of all this.
Ok, the last one last enigma. Honestly. I am heading toward a cranium BLEVE. Here's what the nodes invoked by the normal command-line build load (if I am to trust Process Explorer, which I am probably do not any more). So they all load the M.Build.ni.dll 4.0 from the GAC.
Timestamp of the IL assembly does not match record in .aux file. Loading IL to compare signature.
when Device Guard is enabled which is configured to block certain dlls based on Code Integrity policies. Was this your issue? This seems to be still the case on Windows 11 and seems never to have worked on any Windows version despite MS claiming that the native images when Device Guard is enabled remain usable.
I've attempted to run a multi-node build of a solution (about 15 projects, mix of C# "classic" and F# "SDK" style, all library and desktop executables, with some dependencies on each other), and it failed quite miserably. Essentially, I am modifying the sample's Bulder class. The resolution of DLLS in the controlling process happens just fine, but then it launches a load of nodes (500+ node processes!) it cannot communitcate with. Debugging it (and I even pulled the whole MSBuild and stepped through some code), I cannot understand how that could be possible!
This is Windows 10, net46 build target.
Now my Build method looks like this:
(I noticed XBuild.cs sets up a distributed logger; I tried disconnecting the logger at all, but nothing changed).
Package references
Printed version and locations from
typeof(Project)
inBuild..ctor()
-- I moved it there:What happens is the build progresses very slowly, and the same project is the solution is reported to be build multiple times, according to the log, with the modified logger from the sample, going like
Then, after ~55s, with the whole machine slowed down to a crawl (and it's a decent 8 Core-X CPU, 64GB workstation), the build ends up in an exception:
That's a good hint, actually! When I examined the node processes with the Process Explorer, I learned that the nodes load the 4.0 ngen'd DLLs from the GAC:
while my main process is resolving the correct DLLs. I have only one MSBuild installation, one from the VS15.9.2 payload; it is discovered correctly and all assemblies load into my process from it:
Every node process has the command line
After the build ends, there are 580 nodes, each taking ~2MB or RAM (as opposed to 20-30 when they actually do something)
After some digging through MSBuild source, and figuring out how the nodes are started, I am seriously baffled. I've enable the comm logging
and got a directory of 581 files, one of these not like the others, corresponding to my process PID. The node-produced logs all indeed are waiting for communication, rejecting a request from the wrong M.Build.dll
and the driver launches nodes and is unable to communicate to them
This repeats over and over. Maybe the only notable change is the TID changes from time to time (4 different TIDs are logging, one strictly after the other).
Looking at the process launch code, I am at a loss. The processes are launched with the off-the-shelf native Win32
::CreateProcess()
call. MSBuild.exe.config is perfectly normal, andmsbuld
works from the dev console just fine. How is it possible MSBuild.exe nodes do not see their manifest? I cannot explain, something very tricky is going on!The only thing notable about my setup is I have a directory junction, among others,
C:\_PX\
->C:\Program Files (x86)
; I came to use that setup since Vista times, that (and Windows 7 too) ran out of env space with long paths. For the same reason, I shortenMicrosoft Visual Studio
toMSVS
when first set it up. This is why the paths may vary. (Aside, cmd's env space does not appear to be a problem in Windows 10 any more, but... just in case). This set up has never caused me a problem with any program whatsoever, VS with additional (Intel) C++ compilers, msbuild or multiple other packages, MATLAB, Mathematica, a few Pythons and data sci packages, you name it. Otherwise, everything is perfectly non-hacksy.I do not have the
M.Build*.dll
s in my bin folderI have no unexpected msbuild.exe on PATH
the build-generated
msbuildIntegrated.exe.config
looks normal to meand I swear I did not touch msbuild.exe.config, which has redirects to the same 15.1.0.0 for all DLLs. Besides, it works from command line, or when I launch the process from command line, or from my build tool (that I wanted to replace with the Locator and API calls, but oops).
If there is anything I can do more to trace the issue, please let me know. I am entirely out of ideas. The Locator's handler, even if active, should not affect the nodes launched with a native Win32 API in any way, I believe. So the longer I am looking at the whole issue, the more "it can't happen!" it looks to me. Help!
Adding more info. I captured the Fusion logs, and they are... interesting. Here is MsBuild.exe binding M.Build.dll.
Note added after adding more info: This may or may not be a red herring, as I ran another, normal command line build with the same arguments, carefully wiping all fusion logs and killing nodes between tests and the log entries look exactly same. I think I should stop experimenting with it, or my brain would boil and evaporate. So msbuild.exe 15.0 loads msbuild.ni.exe 4.0 and Microsoft.Build.ni.dll 4.0 from the GAC as its business as usual. Scares last remaining bejeebers out of me.
The "Default" log looks quite normal, and consists all of the same short repeating entry
Native image log entries are strange, and I cannot make sense of them. The same group of 4 entries repeats over and over, and in the end it looks like it happily binds to the GAC version of the 4.0.0.0 assembly.
Baffling. I have not a trace of an idea what to make of all this.
Ok, the last one last enigma. Honestly. I am heading toward a cranium BLEVE. Here's what the nodes invoked by the normal command-line build load (if I am to trust Process Explorer, which I am probably do not any more). So they all load the M.Build.ni.dll 4.0 from the GAC.
If this is true, then all my above analysis is probably worthless. I just do not understand how computers work.
The text was updated successfully, but these errors were encountered: