Sdk: dotnet test output missing in .NET Core 2.1.300 RC1

Created on 8 May 2018 · 9Comments · Source: dotnet/sdk

In .NET Core 2.1 RC1 SDK (2.1.300-rc1-008673), the reason that tests fail is not output to the console anymore. As well as being less useful to the developer, this also appears to break functionality like test output detection in TeamCity.

Steps to reproduce

Clone https://github.com/martincostello/missing-test-output-repo
Run dotnet test

Expected behavior

The reason for the test's failure is output to the console (example below achieved by using 2.0.104 in global.json).

PS C:\Coding\missing-test-output-repo> dotnet test
Build started, please wait...
Build completed.

Test run for C:\Coding\missing-test-output-repo\XUnitTestProject1\bin\Debug\netcoreapp2.0\XUnitTestProject1.dll(.NETCoreApp,Version=v2.0)
Microsoft (R) Test Execution Command Line Tool Version 15.6.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
[xUnit.net 00:00:00.4992229]   Discovering: XUnitTestProject1
[xUnit.net 00:00:00.5743060]   Discovered:  XUnitTestProject1
[xUnit.net 00:00:00.5810979]   Starting:    XUnitTestProject1
[xUnit.net 00:00:00.7636667]     XUnitTestProject1.UnitTest1.Bad_Math [FAIL]
[xUnit.net 00:00:00.7655042]       Assert.Equal() Failure
[xUnit.net 00:00:00.7656693]       Expected: 2
[xUnit.net 00:00:00.7657361]       Actual:   1
[xUnit.net 00:00:00.7671460]       Stack Trace:
[xUnit.net 00:00:00.7688282]         C:\Coding\missing-test-output-repo\XUnitTestProject1\UnitTest1.cs(17,0): at XUnitTe
stProject1.UnitTest1.Bad_Math()
[xUnit.net 00:00:00.7852434]   Finished:    XUnitTestProject1
Failed   XUnitTestProject1.UnitTest1.Bad_Math
Error Message:
 Assert.Equal() Failure
Expected: 2
Actual:   1
Stack Trace:
   at XUnitTestProject1.UnitTest1.Bad_Math() in C:\Coding\missing-test-output-repo\XUnitTestProject1\UnitTest1.cs:line 1
7

Total tests: 2. Passed: 1. Failed: 1. Skipped: 0.
Test Run Failed.
Test execution time: 1.8924 Seconds
PS C:\Coding\missing-test-output-repo>

Actual behavior

Reason for the test's failure is not output, just that the test failed.

PS C:\Coding\missing-test-output-repo> dotnet test
Build started, please wait...
Build completed.

Test run for C:\Coding\missing-test-outputrepo\XUnitTestProject1\bin\Debug\netcoreapp2.0\XUnitTestProject1.dll(.NETCoreApp,Version=v2.0)
Microsoft (R) Test Execution Command Line Tool Version 15.7.0-preview-20180221-13
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
[xUnit.net 00:00:00.7648657]     XUnitTestProject1.UnitTest1.Bad_Math [FAIL]

Total tests: 2. Passed: 1. Failed: 1. Skipped: 0.
Test Run Failed.
Test execution time: 1.9199 Seconds
PS C:\Coding\missing-test-output-repo>

Environment data

dotnet --info output:

PS C:\Coding\missing-test-output-repo> dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.1.300-rc1-008673
 Commit:    f5e3ddbe73

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.16299
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.1.300-rc1-008673\

Host (useful for support):
  Version: 2.1.0-rc1
  Commit:  eb9bc92051

.NET Core SDKs installed:
  1.0.0 [C:\Program Files\dotnet\sdk]
  1.0.1 [C:\Program Files\dotnet\sdk]
  1.0.2 [C:\Program Files\dotnet\sdk]
  1.0.3 [C:\Program Files\dotnet\sdk]
  1.0.4 [C:\Program Files\dotnet\sdk]
  1.1.0 [C:\Program Files\dotnet\sdk]
  2.0.0 [C:\Program Files\dotnet\sdk]
  2.0.2 [C:\Program Files\dotnet\sdk]
  2.0.3 [C:\Program Files\dotnet\sdk]
  2.1.2 [C:\Program Files\dotnet\sdk]
  2.1.3 [C:\Program Files\dotnet\sdk]
  2.1.4 [C:\Program Files\dotnet\sdk]
  2.1.100 [C:\Program Files\dotnet\sdk]
  2.1.101 [C:\Program Files\dotnet\sdk]
  2.1.102 [C:\Program Files\dotnet\sdk]
  2.1.103 [C:\Program Files\dotnet\sdk]
  2.1.104 [C:\Program Files\dotnet\sdk]
  2.1.200 [C:\Program Files\dotnet\sdk]
  2.1.300-preview1-008174 [C:\Program Files\dotnet\sdk]
  2.1.300-preview2-008530 [C:\Program Files\dotnet\sdk]
  2.1.300-rc1-008673 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0-preview1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.0-preview2-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.0-rc1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0-preview1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.0-preview2-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.0-rc1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 1.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.4 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-preview1-26216-03 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-preview2-26406-04 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-rc1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

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

Source

martincostello

👍3

Most helpful comment

Thanks for reporting this issue to us @martincostello! I've made a fix that will be in 2.1 RTM.

peterhuene on 12 May 2018

👍4

All 9 comments

@rainersigwald I believe this may be a fallout of node reuse and output redirection. Can you do a first check?

livarcocc on 9 May 2018

Looks like a VSTest change--something's setting its verbosity to quiet. On my machine the test process is:

"dotnet" exec "C:\Program Files\dotnet\sdk\2.1.300-rc1-008673\vstest.console.dll" --framework:.NETCoreApp,Version=v2.0 s:\repro\missing-test-output-repo\XUnitTestProject1\bin\Debug\netcoreapp2.0\XUnitTestProject1.dll --logger:Console;Verbosity=quiet

Note the last parameter.

Running with a specified verbosity works (with different MSBuild output):

s:\repro\missing-test-output-repo>dotnet test --verbosity=minimal
Waiting for debugger to attach (C:\Program Files\dotnet\dotnet.exe PID 13036).  Press enter to continue...

  Restore completed in 49.55 ms for s:\repro\missing-test-output-repo\XUnitTestProject1\XUnitTestProject1.csproj.
  Restore completed in 84.05 ms for s:\repro\missing-test-output-repo\XUnitTestProject1\XUnitTestProject1.csproj.
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
  XUnitTestProject1 -> s:\repro\missing-test-output-repo\XUnitTestProject1\bin\Debug\netcoreapp2.0\XUnitTestProject1.dll
Build completed.

Test run for s:\repro\missing-test-output-repo\XUnitTestProject1\bin\Debug\netcoreapp2.0\XUnitTestProject1.dll(.NETCoreApp,Version=v2.0)
Microsoft (R) Test Execution Command Line Tool Version 15.7.0-preview-20180221-13
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
[xUnit.net 00:00:00.9192056]     XUnitTestProject1.UnitTest1.Bad_Math [FAIL]
Failed   XUnitTestProject1.UnitTest1.Bad_Math
Error Message:
 Assert.Equal() Failure
Expected: 2
Actual:   1
Stack Trace:
   at XUnitTestProject1.UnitTest1.Bad_Math() in s:\repro\missing-test-output-repo\XUnitTestProject1\UnitTest1.cs:line 17

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

I think this is a result of argument consolidation and cleanup. The test verbosity is set by

https://github.com/dotnet/cli/blob/d0bcc1e6df9de7250aca4c7243c7c6b361b3c75d/src/dotnet/commands/dotnet-test/Program.cs#L63-L72

MSBuild's verbosity inside test is determined by

https://github.com/dotnet/cli/blob/93ff968eba711c994e71bea39f7744301e205d05/src/dotnet/commands/dotnet-test/Program.cs#L34

It used to be

https://github.com/dotnet/cli/blob/10289504a8aeb5fab7c1c9f8e0e7602e9c14250a/src/dotnet/commands/dotnet-test/Program.cs#L34

So that wouldn't have passed the test-verbosity check before, but does now, so MSBuild gets invoked as

"dotnet.exe" exec "C:\Program Files\dotnet\sdk\2.1.300-rc1-008673\MSBuild.dll" -maxcpucount -verbosity:m -restore -target:VSTest -verbosity:quiet -nodereuse:false -nologo -property:VSTestVerbosity=quiet "-distributedlogger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,C:\Program Files\dotnet\sdk\2.1.300-rc1-008673\dotnet.dll*Microsoft.DotNet.Tools.MSBuild.MSBuildForwardingLogger,C:\Program Files\dotnet\sdk\2.1.300-rc1-008673\dotnet.dll"

And passes that down to the VSTest task.

Maybe we could just prepend the -verbosity:quiet to msbuildArgs at the _end_ of TestCommand.FromArgs, preserving the original behavior of always specifying /v:q but allowing it to be overridden by a dotnet test --verbosity: specification?

rainersigwald on 11 May 2018

👍1

Thanks for reporting this issue to us @martincostello! I've made a fix that will be in 2.1 RTM.

peterhuene on 12 May 2018

👍4

Great, thanks @peterhuene! 👍

martincostello on 12 May 2018

@peterhuene Using the workaround above (passing --verbosity=minimal to dotnet test), I'm still not getting test results (names, pass/fail, duration etc.) output to TeamCity during builds. Is that a separate issue, or is a different work around required pending this fix?