dotnet test is incompatible with MSBuild node reuse #1503

rainersigwald · 2018-03-24T12:46:06Z

Description

In the .NET SDK 2.1.300, MSBuild on .NET Core will introduce support for node reuse. This feature enable faster cycle times by keeping MSBuild worker processes alive after the first build ends, allowing them to be reused "hot" by the second and subsequent builds.

Unfortunately, this is incompatible with the output strategy used by VSTestTask, which depends on child processes of MSBuild being attached to the stdout stream of the entry-point dotnet test process. That can't be the case when vstest.console may be run from an MSBuild that has no stdout stream.

On a CLI with the new MSBuild, output from VSTest does not appear on the console.

Steps to reproduce

This is the root cause of the test failures in https://ci.dot.net/job/dotnet_cli/job/release_2.1.2xx/job/release_windows_nt_x64_prtest/41/

On a CLI with the new MSBuild, run dotnet test.

Expected behavior

Test output is displayed from dotnet test regardless of MSBuild internals. From preview1:

s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti>"C:\Program Files\dotnet\dotnet.exe" test
Build started, please wait...
Build completed.

Test run for s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti\bin\Debug\net46\VSTestDesktopAndNetCore.dll(.NETFramework,Version=v4.6)
Microsoft (R) Test Execution Command Line Tool Version 15.6.0-preview-20180109-01
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
Failed   VSTestFailTest
Error Message:
 Assert.Fail failed.
Stack Trace:
   at TestNamespace.VSTestTests.VSTestFailTest()


Total tests: 3. Passed: 2. Failed: 1. Skipped: 0.
Test Run Failed.
Test execution time: 1.8794 Seconds
Test run for s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti\bin\Debug\netcoreapp2.1\VSTestDesktopAndNetCore.dll(.NETCoreApp,Version=v2.1)
Microsoft (R) Test Execution Command Line Tool Version 15.6.0-preview-20180109-01
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
Failed   VSTestFailTest
Error Message:
 Assert.Fail failed.
Stack Trace:
   at TestNamespace.VSTestTests.VSTestFailTest() in s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti\Tests.cs:line 19

Failed   VSTestFailTestNetCoreApp
Error Message:
 Assert.Fail failed.
Stack Trace:
   at TestNamespace.VSTestTests.VSTestFailTestNetCoreApp() in s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti\Tests.cs:line 31


Total tests: 3. Passed: 1. Failed: 2. Skipped: 0.
Test Run Failed.
Test execution time: 1.7366 Seconds

s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti>

Actual behavior

Test output from dotnet test is lost; the build fails without error.

s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti>dotnet test
Build started, please wait...
Build completed.


s:\cli\bin\3\win-x64\test\dotnet-test.Tests\1\VSTestMulti>

AB#1494525

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

smadala · 2018-03-24T14:38:57Z

@rainersigwald I think you are talking about this change. We have did this to show the output in color.

Work around microsoft/vstest#1503 by using the MSBuild escape hatch variable MSBUILDNODEWINDOW and ensuring that tests don't run in a disconnected MSBuild process by passing /nr:false.

rainersigwald · 2018-03-24T17:32:41Z

@smadala That's part of it. Let's discuss options early in the week. The current approach will be really broken going forward.

Work around microsoft/vstest#1503 by using the MSBuild escape hatch variable MSBUILDNODEWINDOW and ensuring that tests don't run in a disconnected MSBuild process by passing /nr:false.

The VSTest runner emits log messages to its stdout. So far, in .NET Core, that has resulted in them getting piped all the way up through the worker MSBuild that launched the task, the entry-point MSBuild coordinating the build, and the `dotnet test` invocation that started it all. The introduction of node reuse for .NET Core makes this untenable: worker nodes should not share stdout with the process that happened to launch them, because they will be long-lived and may do entirely unrelated builds. But for now, this breaks the `dotnet test` scenario. This commit creates an escape hatch environment variable `MSBUILDENSURESTDOUTFORTASKPROCESSES` that can be used in combination with `/nodereuse:false` to create a cone of MSBuild processes that all share std handles. Enables workaround for microsoft/vstest#1503.

Work around microsoft/vstest#1503 by using the MSBuild escape hatch variable MSBUILDENSURESTDOUTFORTASKPROCESSES and ensuring that tests don't run in a disconnected MSBuild process by passing /nr:false.

The VSTest runner emits log messages to its stdout. So far, in .NET Core, that has resulted in them getting piped all the way up through the worker MSBuild that launched the task, the entry-point MSBuild coordinating the build, and the `dotnet test` invocation that started it all. The introduction of node reuse for .NET Core makes this untenable: worker nodes should not share stdout with the process that happened to launch them, because they will be long-lived and may do entirely unrelated builds. But for now, this breaks the `dotnet test` scenario. This commit creates an escape hatch environment variable `MSBUILDENSURESTDOUTFORTASKPROCESSES` that can be used in combination with `/nodereuse:false` to create a cone of MSBuild processes that all share std handles. Enables workaround for microsoft/vstest#1503.

Work around microsoft/vstest#1503 by using the MSBuild escape hatch variable MSBUILDENSURESTDOUTFORTASKPROCESSES and ensuring that tests don't run in a disconnected MSBuild process by passing /nr:false.

smadala · 2018-04-04T14:54:07Z

@rainersigwald Is there any change required from VSTestTask?

smadala · 2018-06-13T13:28:10Z

Below are possible solutions recommended by @rainersigwald

Important scenarios:
- dotnet test on the command line
  - produces minimal, colorized output
- run tests in build otherwise (not a focus so far?)
Rainer will:
- Look into ANSI color-coding passthroughs via logging
  - This would be a nice general solution for everyone: if you log strings with ANSI escape codes they Just Work™
  - OS support? This might have been added in Win10
  - Would require changing VSTest to log messages, but it’d be a contained change to be a ToolTask.
VSTest change possibilities
- Use above if possible
- Write a custom logger to attach via dotnet test
  - Would require changing the VSTest task to log messages.
  - Would also require correctly identifying + colorizing them in the logger
  - Only ideal for dotnet test, somewhat noisy for dotnet msbuild /t:VSTest (but info still always there)
- Run outside MSBuild, using the MSBuild API to build and find test assemblies
  - Gives total control over console output
  - Complex
  - Especially complex since it works for the solution
  - Doesn’t solve the tests-in-build problems

From https://github.com/dotnet/cli/issues/9450#issuecomment-396306035
This is another symptom of #1503. Because VSTest doesn't participate in MSBuild's logging infrastructure, it doesn't get our protections on not interleaving messages.

I don't think there's anything we can do within the current infrastructure to fix this; we need to change VSTest to use logging, and that requires a better colorization-of-logging story.

@rainersigwald Is there a issue tracking "colorization-of-logging"? Or should we go by different approach?

natemcmaster · 2018-07-03T16:52:11Z

Any progress on this? I'm struggling with this right now because VSTest output does not appear on the console or in MSBuild logging. I can't figure out why tests are failing in my build.

Attempt to workaround microsoft/vstest#1503 which causes test failure output to be swallowed

smadala · 2018-08-06T05:26:55Z

@natemcmaster Can you please share sample repo for issue you are facing?

I have tried dotnet msbuild /t:VSTest , I see test failure messages.

PS C:\Users\samadala\src\tmp\msbuild-node-resue> dotnet msbuild /t:VSTest
Microsoft (R) Build Engine version 15.8.86-preview+g4ef6bb1fb2 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

Build started, please wait...
  You are working with a preview version of the .NET Core SDK. You can define the SDK version via a global.json file in the current project. More at https://go.microsoft.com/fwlink/?linkid=869452
  msbuild-node-resue -> C:\Users\samadala\src\tmp\msbuild-node-resue\bin\Debug\netcoreapp2.1\msbuild-node-resue.dll
Build completed.

Test run for C:\Users\samadala\src\tmp\msbuild-node-resue\bin\Debug\netcoreapp2.1\msbuild-node-resue.dll(.NETCoreApp,Version=v2.1)
Microsoft (R) Test Execution Command Line Tool Version 15.8.0-preview-20180605-02
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
[xUnit.net 00:00:00.7505909]     msbuild_node_resue.UnitTest1.Test2 [FAIL]
Failed   msbuild_node_resue.UnitTest1.Test2
Error Message:
 Assert.True() Failure
Expected: True
Actual:   False
Stack Trace:
   at msbuild_node_resue.UnitTest1.Test2() in C:\Users\samadala\src\tmp\msbuild-node-resue\UnitTest1.cs:line 17

Total tests: 2. Passed: 1. Failed: 1. Skipped: 0.
Test Run Failed.
Test execution time: 1.5924 Seconds

FlukeFan · 2018-08-06T08:21:33Z

The following reproduces it for me:

mkdir Project1
cd Project1
dotnet new xunit
cd ..

mkdir Project2
cd Project2
dotnet new xunit
cd ..

dotnet new sln
dotnet sln add Project1\Project1.csproj
dotnet sln add Project2\Project2.csproj

Add the following to Project2\UnitTest1.cs:

    Assert.Equal(1, 2);

Then:

dotnet msbuild /t:VSTest /v:n

I 'think' due to the parallel nature of MSBuild, it can vary which project you have to add the failing test to, but this gives me the following output:

C:\Temp\vstest1503>dotnet msbuild /t:VSTest /v:n
Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

Build started 06/08/2018 09:17:45.
     1>Project "C:\Temp\vstest1503\vstest1503.sln" on node 1 (VSTest target(s)).
Build started, please wait...
     1>Project "C:\Temp\vstest1503\vstest1503.sln" (1) is building "C:\Temp\vstest1503\Project2\Project2.csproj" (2) on node 2 (VSTest target(s)).
     2>Project "C:\Temp\vstest1503\Project2\Project2.csproj" (2) is building "C:\Temp\vstest1503\Project2\Project2.csproj" (2:2) on node 2 (default targets).
     2>GenerateTargetFrameworkMonikerAttribute:
       Skipping target "GenerateTargetFrameworkMonikerAttribute" because all output files are up-to-date with respect to the input files.
       CoreGenerateProgramFile:
       Skipping target "CoreGenerateProgramFile" because all output files are up-to-date with respect to the input files.
       CoreGenerateAssemblyInfo:
       Skipping target "CoreGenerateAssemblyInfo" because all output files are up-to-date with respect to the input files.
       CoreCompile:
       Skipping target "CoreCompile" because all output files are up-to-date with respect to the input files.
       _CopyOutOfDateSourceItemsToOutputDirectory:
       Skipping target "_CopyOutOfDateSourceItemsToOutputDirectory" because all output files are up-to-date with respect to the input files.
       GenerateBuildDependencyFile:
       Skipping target "GenerateBuildDependencyFile" because all output files are up-to-date with respect to the input files.
       GenerateBuildRuntimeConfigurationFiles:
       Skipping target "GenerateBuildRuntimeConfigurationFiles" because all output files are up-to-date with respect to the input files.
       CopyFilesToOutputDirectory:
         Project2 -> C:\Temp\vstest1503\Project2\bin\Debug\netcoreapp2.1\Project2.dll
     2>Done Building Project "C:\Temp\vstest1503\Project2\Project2.csproj" (default targets).
     1>Project "C:\Temp\vstest1503\vstest1503.sln" (1) is building "C:\Temp\vstest1503\Project1\Project1.csproj" (3) on node 1 (VSTest target(s)).
     3>Project "C:\Temp\vstest1503\Project1\Project1.csproj" (3) is building "C:\Temp\vstest1503\Project1\Project1.csproj" (3:2) on node 1 (default targets).
     3>GenerateTargetFrameworkMonikerAttribute:
       Skipping target "GenerateTargetFrameworkMonikerAttribute" because all output files are up-to-date with respect to the input files.
       CoreGenerateProgramFile:
       Skipping target "CoreGenerateProgramFile" because all output files are up-to-date with respect to the input files.
       CoreGenerateAssemblyInfo:
       Skipping target "CoreGenerateAssemblyInfo" because all output files are up-to-date with respect to the input files.
       CoreCompile:
       Skipping target "CoreCompile" because all output files are up-to-date with respect to the input files.
       _CopyOutOfDateSourceItemsToOutputDirectory:
       Skipping target "_CopyOutOfDateSourceItemsToOutputDirectory" because all output files are up-to-date with respect to the input files.
       GenerateBuildDependencyFile:
       Skipping target "GenerateBuildDependencyFile" because all output files are up-to-date with respect to the input files.
       GenerateBuildRuntimeConfigurationFiles:
       Skipping target "GenerateBuildRuntimeConfigurationFiles" because all output files are up-to-date with respect to the input files.
       CopyFilesToOutputDirectory:
         Project1 -> C:\Temp\vstest1503\Project1\bin\Debug\netcoreapp2.1\Project1.dll
     3>Done Building Project "C:\Temp\vstest1503\Project1\Project1.csproj" (default targets).
Build completed.

Test run for C:\Temp\vstest1503\Project1\bin\Debug\netcoreapp2.1\Project1.dll(.NETCoreApp,Version=v2.1)
Microsoft (R) Test Execution Command Line Tool Version 15.7.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
     2>Done Building Project "C:\Temp\vstest1503\Project2\Project2.csproj" (VSTest target(s)) -- FAILED.

Total tests: 1. Passed: 1. Failed: 0. Skipped: 0.
Test Run Successful.
Test execution time: 2.3674 Seconds
     3>Done Building Project "C:\Temp\vstest1503\Project1\Project1.csproj" (VSTest target(s)).
     1>Done Building Project "C:\Temp\vstest1503\vstest1503.sln" (VSTest target(s)) -- FAILED.

Build FAILED.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:03.71

Note, build failed, but no output of Project2 tests.

smadala · 2018-08-06T08:22:57Z

@FlukeFan Thanks for repro steps. Let me try them.

smadala · 2018-08-06T08:23:53Z

@FlukeFan FYI my msbuild verions 15.8.86-preview+g4ef6bb1fb2

FlukeFan · 2018-08-06T08:30:29Z

You can also see the workaround here:
https://github.com/dotnet/cli/blob/master/src/dotnet/commands/dotnet-test/Program.cs#L35

My understanding is that a lot of the build performance improvement comes from paralellization of the build, but that certain (console, I think) output is lost when doing this. The workaround turns off the paralellism for dotnet test, but not for dotnet msbuild I think.

smadala · 2018-08-06T09:04:59Z

@FlukeFan I'm able to repro the issue when invoking /t:VSTest solution/directory level.

Unfortunately /t:VSTest won't support from solution/directory level. We are tracking #705 #411 to address it.

@rainersigwald @natemcmaster I observer that using /nodereuse:false at solution/directory level( dotnet msbuild /t:VSTest /v:n /nodereuse:false) not helping to get output of /t:VSTest. Is that expected?

rainersigwald · 2018-08-06T14:42:56Z

using /nodereuse:false at solution/directory level(dotnet msbuild /t:VSTest /v:n /nodereuse:false) not helping to get output of /t:VSTest. Is that expected?

Yes, it is. As a workaround you can set the environment variable MSBUILDENSURESTDOUTFORTASKPROCESSES=1 in addition to passing /nodereuse:false. That changes the way MSBuild creates child processes to force them to share a stdout stream with the parent.

The dotnet cli uses this workaround when you invoke dotnet test. @FlukeFan the build is still parallel in the dotnet test case, but it doesn't reuse MSBuild worker nodes, so there's slightly more overhead than usual.

When tests run in CI, we are not displaying the test output to the console. So if a test fails, and for some reason the .trx file isn't parsed correctly, it is impossible to see what test failed and why. The test output isn't being displayed because of microsoft/vstest#1503. To work around the vstest bug, split CI builds into 2 separate MSBuild invocations: one to do the build (which is multi-proc) and another to run the tests (which doesn't need MSBuild node reuse).

jachin84 · 2021-05-17T11:52:10Z

I just hit this today and I'm wondering if there is a proper fix for this yet?

mcartoixa · 2021-05-17T12:35:18Z

I just hit this today and I'm wondering if there is a proper fix for this yet?

There is a workaround in PR #2702 (use dotnet msbuild instead of dotnet test: loose pretty colorization and gain proper MSBuild integration). The PR has never even been discussed yet, though...

jachin84 · 2021-05-18T06:36:08Z

I am already using dotnet msbuild. I am assuming you mean after #2702 is merged?

mcartoixa · 2021-05-18T07:51:45Z

If it is ever merged, indeed.

jachin84 · 2021-05-18T10:05:45Z

What's holding it up do you think?

jachin84 · 2021-05-24T23:32:10Z

@smadala are you still actively working on this issue?

nohwnd · 2024-07-09T08:49:46Z

This was solved in net9 together with terminal logger.

FlukeFan · 2024-07-18T14:56:20Z

This was solved in net9 together with terminal logger.

I tried updating to 9.0.100-preview.6.24328.19 ... and the output I get (from my above example) is:

dotnet msbuild /t:VSTest --tl:true
You are using a preview version of .NET. See: https://aka.ms/dotnet-support-policy
  Project2 succeeded (0.1s) → Project2\bin\Debug\net9.0\Project2.dll
  Project1 succeeded (0.3s) → Project1\bin\Debug\net9.0\Project1.dll
  Project2                                                                     ShowCallOfVSTestTaskWithParameter (0.3s)
  Project1                                                                     ShowCallOfVSTestTaskWithParameter (0.0s)
  Project2                                                                     ShowCallOfVSTestTaskWithParameter (0.1s)
VSTest version 17.11.0-preview-24320-06 (x64)                                                                    (0.2s)
                                                                                                                 (0.5s)
  Project1                                                                     ShowCallOfVSTestTaskWithParameter (0.7s)


Build failed in 1.4s

So it's not telling me where it failed. What am I missing?

nohwnd · 2024-07-22T07:26:02Z

The issue was about dotnet test, and that works.

But you are right dotnet msbuild /t:vstest still does not work correctly with terminal logger.

nohwnd · 2024-07-22T07:29:29Z

Moved to new issue: #5156

rainersigwald mentioned this issue Mar 24, 2018

MSBuild 15.7.124 for 2.1.3xx dotnet/cli#8884

Merged

rainersigwald mentioned this issue Mar 24, 2018

Escape hatch: share stdout with node children dotnet/msbuild#3130

Merged

smadala added the question label Mar 29, 2018

natemcmaster mentioned this issue Mar 30, 2018

VSTest output not displayed on console output on Windows aspnet/BuildTools#623

Closed

singhsarab assigned pvlakshm May 23, 2018

singhsarab assigned smadala Jun 8, 2018

smadala added enhancement and removed question labels Jun 19, 2018

natemcmaster pushed a commit to aspnet/Universe that referenced this issue Jul 3, 2018

Invoke dotnet vstest directly instead of using the VSTest target

d2d9a47

Attempt to workaround microsoft/vstest#1503 which causes test failure output to be swallowed

eerhardt mentioned this issue Aug 6, 2018

Fix test output during CI. dotnet/machinelearning#652

Merged

mcartoixa mentioned this issue Jan 16, 2021

Create a proper MSBuild ToolTask based VSTestTask #2702

Merged

mcartoixa mentioned this issue Feb 8, 2022

VSTestTask only logs to the console #680

Closed

pavelhorak added the sprint label Mar 7, 2022

AR-May mentioned this issue Jul 15, 2022

Do not use msbuild server with escape hatch for VSTestTask enabled. dotnet/msbuild#7829

Merged

Evangelink unassigned smadala and pvlakshm Aug 3, 2022

Evangelink added the needs-triage This item should be discussed in the next triage meeting. label Aug 3, 2022

Piedone mentioned this issue Nov 16, 2022

UI testing randomly getting stuck in CI (OSOE-464) Lombiq/UI-Testing-Toolbox#228

Open

9 tasks

Evangelink removed sprint needs-triage This item should be discussed in the next triage meeting. labels Nov 30, 2022

JanKrivanek mentioned this issue Jul 24, 2023

[Bug]: Output mangled when Terminal Logger used in combination with dotnet test dotnet/msbuild#9061

Closed

pavelhorak assigned nohwnd Jul 31, 2023

pavelhorak added this to the Future milestone Jul 31, 2023

nohwnd removed this from the Future milestone Aug 3, 2023

tmds mentioned this issue Aug 29, 2023

process.StandardOutput.ReadToEnd() never finishes for dotnet build in unit tests in certain situations on Windows dotnet/sdk#34653

Open

JanKrivanek mentioned this issue Nov 1, 2023

Terminal Logger: Rewritable Logger API spec dotnet/msbuild#9378

Closed

nohwnd closed this as not planned Won't fix, can't repro, duplicate, stale Jul 9, 2024

nohwnd reopened this Jul 9, 2024

nohwnd closed this as completed Jul 9, 2024

nohwnd mentioned this issue Jul 22, 2024

dotnet msbuild /t:VSTest does not work with terminal logger #5156

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

dotnet test is incompatible with MSBuild node reuse #1503

dotnet test is incompatible with MSBuild node reuse #1503

rainersigwald commented Mar 24, 2018 •

edited

Loading

smadala commented Mar 24, 2018

rainersigwald commented Mar 24, 2018

smadala commented Apr 4, 2018

smadala commented Jun 13, 2018

natemcmaster commented Jul 3, 2018

smadala commented Aug 6, 2018

FlukeFan commented Aug 6, 2018

smadala commented Aug 6, 2018

smadala commented Aug 6, 2018

FlukeFan commented Aug 6, 2018

smadala commented Aug 6, 2018

rainersigwald commented Aug 6, 2018

jachin84 commented May 17, 2021

mcartoixa commented May 17, 2021

jachin84 commented May 18, 2021 •

edited

Loading

mcartoixa commented May 18, 2021

jachin84 commented May 18, 2021

jachin84 commented May 24, 2021

nohwnd commented Jul 9, 2024

FlukeFan commented Jul 18, 2024 •

edited

Loading

nohwnd commented Jul 22, 2024

nohwnd commented Jul 22, 2024

dotnet test is incompatible with MSBuild node reuse #1503

dotnet test is incompatible with MSBuild node reuse #1503

Comments

rainersigwald commented Mar 24, 2018 • edited Loading

Description

Steps to reproduce

Expected behavior

Actual behavior

smadala commented Mar 24, 2018

rainersigwald commented Mar 24, 2018

smadala commented Apr 4, 2018

smadala commented Jun 13, 2018

natemcmaster commented Jul 3, 2018

smadala commented Aug 6, 2018

FlukeFan commented Aug 6, 2018

smadala commented Aug 6, 2018

smadala commented Aug 6, 2018

FlukeFan commented Aug 6, 2018

smadala commented Aug 6, 2018

rainersigwald commented Aug 6, 2018

jachin84 commented May 17, 2021

mcartoixa commented May 17, 2021

jachin84 commented May 18, 2021 • edited Loading

mcartoixa commented May 18, 2021

jachin84 commented May 18, 2021

jachin84 commented May 24, 2021

nohwnd commented Jul 9, 2024

FlukeFan commented Jul 18, 2024 • edited Loading

nohwnd commented Jul 22, 2024

nohwnd commented Jul 22, 2024

rainersigwald commented Mar 24, 2018 •

edited

Loading

jachin84 commented May 18, 2021 •

edited

Loading

FlukeFan commented Jul 18, 2024 •

edited

Loading