Vstest: dotnet test is incompatible with MSBuild node reuse

[rainersigwald]

(I plan to submit a PR for this shortly)

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>

[smadala]

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

[rainersigwald]

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

[smadala]

@rainersigwald Is there any change required from VSTestTask?

[smadala]

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 Microsoft/vstest#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]

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.

[smadala]

@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]

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]

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

[smadala]

@FlukeFan FYI my msbuild verions 15.8.86-preview+g4ef6bb1fb2

[FlukeFan]

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]

@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 https://github.com/Microsoft/vstest/issues/705 https://github.com/Microsoft/vstest/issues/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]

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.

[mcartoixa]

Hi, coming (late) from #680: it seems that this colorization against logging issue has spread all over different repositories now...

My take on this is that:

• MSBuild is a very mature environment with a robust and tested logging system. If we are to integrate with it, we should do it properly. Right now this means losing fancy colorization, but in a twist of fate this also means gaining some level of colorization (yellow for warnings and red for errors). AppVeyor (for instance) can handle that just fine.
• Fancy colorization is fine for console users, though not worth the price we are paying right now IMHO.

Today I can see 3 ways to execute tests from the command line:

• dotnet test Project.sln: this executes MSBuild behind the hood, which executes dotnet exec vstest.console.dll. As we require colorization of the output for the end user there we lose logging capability.
• dotnet vstest Project.sln: same as above.
• dotnet msbuild Project.sln --target VSTest: invokes MSBuild directly, which executes dotnet exec vstest.console.dll. As it is the same as above we lose logging capability.

One way forward could be:

• restore logging to MSBuild (and thus lose colorization).
• skip MSBuild and execute dotnet exec vstest.console.dll directly when called from dotnet test: colorization would be fine.
  
  
  
  • one drawback is that for this command to be able to build the specified projects before testing them it may be necessary to call MSBuild beforehand inside the same command. And some command line options would have to be reviewed.
  
  

Or we could implement 2 MSBuild tasks used in different targets:

• one specifically called via dotnet test that does not log and colorizes its output.
• one used by default in MSBuild that logs properly and does not colorize...

Note that I would be able to submit PRs either way (I have already done some work on the first scenario).

[jachin84]

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

[mcartoixa]

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]

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

[mcartoixa]

_If_ it is ever merged, indeed.

[jachin84]

What's holding it up do you think?

[jachin84]

@smadala are you still actively working on this issue?