Runtime: Common job failure: msbuild MSB4166 error

[BruceForstall]

This seems to be a common, non-repeatable, job failure reason for the Linux arm64 jobs (maybe others as well?)

MSBUILD : error MSB4166: Child node "2" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.

This seems to mostly occur during the Docker build of the tests.

E.g.,
https://ci.dot.net/job/dotnet_coreclr/job/master/job/arm64_cross_checked_ubuntu16.04_innerloop/43/consoleFull

[BruceForstall]

e.g.,
https://ci.dot.net/job/dotnet_coreclr/job/master/job/arm64_cross_checked_ubuntu16.04/489/consoleFull#-182808793679494335-f7bd-47d0-8771-8661e00c2db2

[shimingsg]

e.g.,
https://ci.dot.net/job/dotnet_coreclr/job/master/job/checked_ubuntu/24962/consoleFull#196667680279494335-f7bd-47d0-8771-8661e00c2db2

[jiangzeng]

Similar failure in x86_checked_windows_nt_corefx_minopts:
https://ci.dot.net/job/dotnet_coreclr/job/master/view/x86/job/jitstress/job/x86_checked_windows_nt_corefx_minopts/618/

Log:
MSBUILD : error MSB4166: Child node "3" exited prematurely. Shutting down. Diagnostic information may be found in files in "C:\Users\dotnet-bot\AppData\Local\Temp\" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.

[janvorli]

I got it in my PR today too:
https://ci.dot.net/job/dotnet_coreclr/job/master/job/x64_checked_centos7.1_innerloop_prtest/9295
And I am hitting it in my private builds on my local Ubuntu 16.04 machine too.

[BruceForstall]

@RussKeldorph Is this something someone from the msbuild team could/should help diagnose and debug? Do you have a contact?

[RussKeldorph]

@rainersigwald Any suggestions?

[sandreenko]

I hit the same issue locally and it is stable, does anybody know a workaround for it?

MSBUILD : error MSB4166: Child node "3" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
/home/sergey/git/coreclr/_/fx/.dotnet/sdk/2.1.401/NuGet.targets(114,5): error : Restore canceled! [/home/sergey/git/coreclr/_/fx/external/ILLink/ILLink.depproj]
/home/sergey/git/coreclr/_/fx/.dotnet/sdk/2.1.401/NuGet.targets(114,5): error : Restore canceled! [/home/sergey/git/coreclr/_/fx/external/test-runtime/XUnit.Runtime.depproj]
    8 Warning(s)
    3 Error(s)

[rainersigwald]

Are there any logs in /tmp/?

[sandreenko]

Are there any logs in /tmp/?

I do not see any with MSBuild_*.failure.txt, I can give you access to this machine if you want.

[sandreenko]

Nobody is currently working on this,
@rainersigwald did some initial diagnostic steps on my machine, he was able to repro it, but not with single proc build. The additional logging also did not reveal the issue.

[sandreenko]

Link dotnet/corefx#33595, it covers fails on ubuntu 18.04 when build corefx.

[echesakovMSFT]

The issue is now hitting Azure DevOps CI build and test jobs.

For example, in https://dnceng.visualstudio.com/public/_build/results?buildId=70179 Test pri0 Linux_musl x64 checked Job has failed with:

2019-01-10T19:18:33.2451899Z MSBUILD : error MSB4166: Child node "2" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
2019-01-10T19:18:33.2764510Z 
2019-01-10T19:18:33.2768447Z Build FAILED.
2019-01-10T19:18:33.2768538Z 
2019-01-10T19:18:33.2768768Z MSBUILD : error MSB4166: Child node "2" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
2019-01-10T19:18:33.2777524Z     0 Warning(s)
2019-01-10T19:18:33.2778197Z     1 Error(s)
2019-01-10T19:18:33.2778269Z 
2019-01-10T19:18:33.2778475Z Time Elapsed 00:04:05.08
2019-01-10T19:18:33.3742116Z Command execution failed with exit code 1.
2019-01-10T19:18:33.3775644Z ERROR: An error occured in /__w/1/s/Tools/dotnetcli/dotnet /__w/1/s/Tools/run.exe /__w/1/s/config.json build -Project=/__w/1/s/tests/build.proj -MsBuildLog=/flp:Verbosity=normal;LogFile=/__w/1/s/bin/Logs/Tests_Managed.Linux.x64.Checked.log;Append=true -MsBuildWrn=/flp1:WarningsOnly;LogFile=/__w/1/s/bin/Logs/Tests_Managed.Linux.x64.Checked.wrn;Append=true -MsBuildErr=/flp2:ErrorsOnly;LogFile=/__w/1/s/bin/Logs/Tests_Managed.Linux.x64.Checked.err;Append=true -MsBuildEventLogging=/l:BinClashLogger,Tools/Microsoft.DotNet.Build.Tasks.dll;LogFile=binclash.log -BuildArch=x64 -BuildType=Checked -BuildOS=Linux. Check logs under /__w/1/s.
2019-01-10T19:18:33.3778658Z Failed to build Managed tests build (build tests). See the build logs:
2019-01-10T19:18:33.3778923Z     /__w/1/s/bin/Logs/Tests_Managed.Linux.x64.Checked.log
2019-01-10T19:18:33.3779281Z     /__w/1/s/bin/Logs/Tests_Managed.Linux.x64.Checked.wrn
2019-01-10T19:18:33.3780309Z     /__w/1/s/bin/Logs/Tests_Managed.Linux.x64.Checked.err
2019-01-10T19:18:33.3905727Z ##[error]Bash exited with code '1'.

@RussKeldorph This would very costly failure as soon as we switch to Azure DevOps CI since now if only one job fails in order to properly validate PR you would need to restart all the jobs (default or custom triggered) and hope that MSBuild won't fail again.

[echesakovMSFT]

@rainersigwald Can you please share techniques we can use to narrow down the issue? I was thinking about enabling /bl in our CI?

Is there any way to enable collecting memory consumption stats in MSBuild? I suspect one of the child project could be killed due to OOM but have yet to confirm this. We had an issue in the past with excessive memory consumption https://github.com/Microsoft/msbuild/issues/2993

[BruceForstall]

I'm still seeing this frequently in Linux/arm64 cross builds (in Docker on Linux/x64), e.g.:

https://ci.dot.net/job/dotnet_coreclr/job/master/job/arm64_cross_checked_ubuntu16.04/3566

MSBUILD : error MSB4166: Child node "3" exited prematurely. Shutting down. Diagnostic information may be found in files in "/tmp/" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.

I've never seen any MSBuild_*.failure.txt files when it's happened locally. We could attempt to log these files in Jenkins and see if there are any after a fail.

[echesakovMSFT]

This could be due to https://github.com/dotnet/coreclr/issues/18044

I did an experiment with running build-test.sh under Docker in two modes: swap enabled and swap disabled and also limited an amount of memory available to a Docker container to 256Mb.

When swap is enabled the build proceeds fine while keeping container memory usage around 256 Mb.
When swap is disabled MSBuild almost immediately fails (when MSBuild starts calling C# compiler) with the exactly same message MSBUILD : error MSB4166: Child node "3" exited prematurely. Shutting down.

As expected, dmesg shows dotnet process got killed by OOM killer.

/cc @RussKeldorph

[ajain04]

Is this fix available in .NET Core 2.1.9 release?

[BruceForstall]

@echesakovMSFT @RussKeldorph I'm seeing this in AzDO runs (where it is much harder to find -- I have to click a bunch more to find the failure message).

Is there a plan to "fix" this?

[BruceForstall]

Another failure:
https://dev.azure.com/dnceng/public/_build/results?buildId=128982&view=logs&jobId=4ca8f40e-d352-5444-a18c-d0f1216adfe9

[kichalla]

We are seeing this error randomly in our CI agents. And when I look at the /tmp folder for files of type MSBUILD-*.failure.txt, I see the following content:

7/11/19 3:42:06 PM
System.IO.FileNotFoundException: Unable to find the specified file.
   at Interop.Sys.GetCwdHelper(Byte* ptr, Int32 bufferSize)
   at Interop.Sys.GetCwd()
   at System.Environment.get_CurrentDirectory()
   at System.IO.Directory.GetCurrentDirectory()
   at Microsoft.Build.BackEnd.RequestBuilder.ReportResultAndCleanUp(BuildResult result)
   at Microsoft.Build.BackEnd.RequestBuilder.BuildAndReport()
   at Microsoft.Build.BackEnd.RequestBuilder.RequestThreadProc(Boolean setThreadParameters)
===================

Few things to note:

1. We are building in a Ubuntu 16.04.6 LTS based VM.
2. I do not see the MSBUILD-*.failure.txt getting created always.
3. dotnet --info:

.NET Core SDK (reflecting any global.json):
 Version:   2.2.300
 Commit:    73efd5bd87

Runtime Environment:
 OS Name:     ubuntu
 OS Version:  16.04
 OS Platform: Linux
 RID:         ubuntu.16.04-x64
 Base Path:   /usr/share/dotnet/sdk/2.2.300/

Host (useful for support):
  Version: 2.2.5
  Commit:  0a3c9209c0

.NET Core SDKs installed:
  2.2.300 [/usr/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.2.5 [/usr/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.2.5 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.2.5 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

To install additional .NET Core runtimes or SDKs:
  https://aka.ms/dotnet-download

[sercanparan]

We've encountered this while multiple pipelines are trying to build different projects stored in a single solution (single repo)
-- hope it helps.

[kichalla]

Any suggestions regarding this? We are still hitting this issue randomly. Does setting MSBUILDDISABLENODEREUSE=1 in anyway help? I am going to try it out...

[TakhiAbed]

@kichalla did setting MSBUILDDISABLENODEREUSE=1 helped?

[BruceForstall]

Haven't seen this in a while, so closing. Feel free to re-open if it occurs again.

[bliles]

Seeing this error on our build server whenever two dotnet builds are running at the same time. Setting MSBUILDDISABLENODEREUSE=1 did help.