`VSTestTask` only logs to the console

[dougbu]

Description

File logging output contains information about calling the VSTestTask but no output from the task itself. This makes it difficult to search the test's output.

Steps to reproduce

Appears to occur with every ASP.NET repo. For example,

1. git clone https://github.com/aspnet/HtmlAbstractions.git
2. cd HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests
3. dotnet restore
4. dotnet build
5. dotnet test --no-build --framework netcoreapp2.0 /flp:verbosity=diag
6. notepad msbuild.log

Expected behavior

Same information in the msbuild.log file as was shown on the console:

Test run for C:\dd\dnx\Universe\.r\HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests\bin\Debug\netcoreapp2.0\Microsoft.Extensions.WebEncoders.Tests.dll(.NETCoreApp,Version=v2.0)
Microsoft (R) Test Execution Command Line Tool Version 15.0.0.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
[xUnit.net 00:00:00.4636575]   Discovering: Microsoft.Extensions.WebEncoders.Tests
[xUnit.net 00:00:00.5966555]   Discovered:  Microsoft.Extensions.WebEncoders.Tests
[xUnit.net 00:00:00.6391310]   Starting:    Microsoft.Extensions.WebEncoders.Tests
[xUnit.net 00:00:00.8075514]   Finished:    Microsoft.Extensions.WebEncoders.Tests

Total tests: 6. Passed: 6. Failed: 0. Skipped: 0.
Test Run Successful.
Test execution time: 1.9789 Seconds

Actual behavior

Information around the VSTestTask call but nothing from the task itself:

12:23:02.754     1>Target "VSTest: (TargetId:2)" in file "C:\Users\dougbu\AppData\Local\Microsoft\dotnet\sdk\2.0.0-preview1-005418\Microsoft.TestPlatform.targets" from project "C:\dd\dnx\Universe\.r\HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests\Microsoft.Extensions.WebEncoders.Tests.csproj" (entry point):
                   Task "CallTarget" skipped, due to false condition; ('$(VSTestNoBuild)' != 'true') was evaluated as ('true' != 'true').
                   Using "CallTarget" task from assembly "Microsoft.Build.Tasks.Core, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a".
                   Task "CallTarget" (TaskId:2)
                     Task Parameter:Targets=ShowCallOfVSTestTaskWithParameter (TaskId:2)
12:23:02.772     1>Target "ShowCallOfVSTestTaskWithParameter: (TargetId:3)" in file "C:\Users\dougbu\AppData\Local\Microsoft\dotnet\sdk\2.0.0-preview1-005418\Microsoft.TestPlatform.targets" from project "C:\dd\dnx\Universe\.r\HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests\Microsoft.Extensions.WebEncoders.Tests.csproj" (target "VSTest" depends on it):
                   Using "Message" task from assembly "Microsoft.Build.Tasks.Core, Version=15.1.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a".
                   Task "Message" (TaskId:3)
                     Task Parameter:Text=Calling task Microsoft.TestPlatform.Build.Tasks.VSTestTask with following parameter... (TaskId:3)
                     Task Parameter:Importance=low (TaskId:3)
                     Calling task Microsoft.TestPlatform.Build.Tasks.VSTestTask with following parameter... (TaskId:3)
                   Done executing task "Message". (TaskId:3)
                   Task "Message" (TaskId:4)
                     Task Parameter:Text=TestFileFullPath = C:\dd\dnx\Universe\.r\HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests\bin\Debug\netcoreapp2.0\Microsoft.Extensions.WebEncoders.Tests.dll (TaskId:4)
                     Task Parameter:Importance=low (TaskId:4)
                     TestFileFullPath = C:\dd\dnx\Universe\.r\HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests\bin\Debug\netcoreapp2.0\Microsoft.Extensions.WebEncoders.Tests.dll (TaskId:4)
                   Done executing task "Message". (TaskId:4)
                   Task "Message" (TaskId:5)
                     Task Parameter:Text=VSTestSetting =  (TaskId:5)
                     Task Parameter:Importance=low (TaskId:5)
                     VSTestSetting =  (TaskId:5)
                   Done executing task "Message". (TaskId:5)
                   Task "Message" (TaskId:6)
                     Task Parameter:Text=VSTestTestAdapterPath =  (TaskId:6)
                     Task Parameter:Importance=low (TaskId:6)
                     VSTestTestAdapterPath =  (TaskId:6)
                   Done executing task "Message". (TaskId:6)
                   Task "Message" (TaskId:7)
                     Task Parameter:Text=VSTestFramework = .NETCoreApp,Version=v2.0 (TaskId:7)
                     Task Parameter:Importance=low (TaskId:7)
                     VSTestFramework = .NETCoreApp,Version=v2.0 (TaskId:7)
                   Done executing task "Message". (TaskId:7)
                   Task "Message" (TaskId:8)
                     Task Parameter:Text=VSTestPlatform =  (TaskId:8)
                     Task Parameter:Importance=low (TaskId:8)
                     VSTestPlatform =  (TaskId:8)
                   Done executing task "Message". (TaskId:8)
                   Task "Message" (TaskId:9)
                     Task Parameter:Text=VSTestTestCaseFilter =  (TaskId:9)
                     Task Parameter:Importance=low (TaskId:9)
                     VSTestTestCaseFilter =  (TaskId:9)
                   Done executing task "Message". (TaskId:9)
                   Task "Message" (TaskId:10)
                     Task Parameter:Text=VSTestLogger =  (TaskId:10)
                     Task Parameter:Importance=low (TaskId:10)
                     VSTestLogger =  (TaskId:10)
                   Done executing task "Message". (TaskId:10)
                   Task "Message" (TaskId:11)
                     Task Parameter:Text=VSTestListTests =  (TaskId:11)
                     Task Parameter:Importance=low (TaskId:11)
                     VSTestListTests =  (TaskId:11)
                   Done executing task "Message". (TaskId:11)
                   Task "Message" (TaskId:12)
                     Task Parameter:Text=VSTestDiag =  (TaskId:12)
                     Task Parameter:Importance=low (TaskId:12)
                     VSTestDiag =  (TaskId:12)
                   Done executing task "Message". (TaskId:12)
                   Task "Message" (TaskId:13)
                     Task Parameter:Text=VSTestCLIRunSettings =  (TaskId:13)
                     Task Parameter:Importance=low (TaskId:13)
                     VSTestCLIRunSettings =  (TaskId:13)
                   Done executing task "Message". (TaskId:13)
12:23:02.774     1>Done building target "ShowCallOfVSTestTaskWithParameter" in project "Microsoft.Extensions.WebEncoders.Tests.csproj".: (TargetId:3)
                   Done executing task "CallTarget". (TaskId:2)
                   Using "Microsoft.TestPlatform.Build.Tasks.VSTestTask" task from assembly "C:\Users\dougbu\AppData\Local\Microsoft\dotnet\sdk\2.0.0-preview1-005418\Microsoft.TestPlatform.Build.dll".
                   Task "Microsoft.TestPlatform.Build.Tasks.VSTestTask" (TaskId:14)
                     Task Parameter:TestFileFullPath=C:\dd\dnx\Universe\.r\HtmlAbstractions\test\Microsoft.Extensions.WebEncoders.Tests\bin\Debug\netcoreapp2.0\Microsoft.Extensions.WebEncoders.Tests.dll (TaskId:14)
                     Task Parameter:VSTestFramework=.NETCoreApp,Version=v2.0 (TaskId:14)
                   Done executing task "Microsoft.TestPlatform.Build.Tasks.VSTestTask". (TaskId:14)
12:23:05.787     1>Done building target "VSTest" in project "Microsoft.Extensions.WebEncoders.Tests.csproj".: (TargetId:2)

Environment

Not sure how long this issue has been happening. We don't have MSBuild logs from that far back. The following describes my current environment.

Please share additional details about the test environment.

dotnet --info

.NET Command Line Tools (2.0.0-preview1-005418)

Product Information:
 Version:            2.0.0-preview1-005418
 Commit SHA-1 hash:  82c928e1ec

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.14393
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Users\dougbu\AppData\Local\Microsoft\dotnet\sdk\2.0.0-preview1-005418\

Operating system, Build version of vstest.console

Logging above mentions "C:\Users\dougbu\AppData\Local\Microsoft\dotnet\sdk\2.0.0-preview1-005418\Microsoft.TestPlatform.Build.dll".

[codito]

@dougbu can you elaborate little more on the scenario? Is the user intention to customize/diagnose build parameters for vstest task? Is it in the CI or devbox? Can the stdout/stderr redirection with dotnet test -f netcoreapp2.0 2> vstest.log or dotnet test -f netcoreapp2.0 | tee vstest.log help?

[dougbu]

The scenario is diagnosing test failure, reviewing what the tests output. If diagnosing the task parameters were of interest, the minimal logging from the task would be useful.

This is on a developer's machine. By default, we run our command-line builds with a file logger for detailed output. The log file is very useful for searches, reviewing data lost in screenfulls of output, and occasionally for the extra MSBuild info. Turns out the log file is useless for reviewing or diagnosing tests failures.

Redirecting the output works but isn't particularly helpful. That requires additional test runs and usually comes after wasting time looking at the log file.

Bottom line, VSTestTask ignores configured file loggers in particular. Why? (Doesn't seem to pay much attention to the console verbosity level either. But, that seems separate.)

[codito]

Thanks for clarification. We need to wire this in.

Possibly use ToolTask (https://msdn.microsoft.com/en-us/library/microsoft.build.utilities.tooltask.aspx) for VSTestTask implementation or listen to stderr/stdout of vstest.console.

[mcartoixa]

Bump.

My tests work fine on my machine but fail on the build server (AppVeyor). There I can only access the MSbuild logs, and as there is no output I am completely blind...

.NET Core 3.0 preview 7

BTW I have some experience with MSBuild tasks and may be able to contribute. Can I submit a PR directly?

[mcartoixa]

Anyone?

I have tried to base VSTestTask on Tooltask as suggested as it seems the right thing to do to enjoy the benefits of a whole infrastructure, including the ability to automatically log the output. Unfortunately my work proves very difficult to test: the generated assemble does not seem to work simply as a drop in in .NET Core 3.0 preview 7. I figure this is because it targets .NET Standard 2.0, whereas the assembly shipped with .NEt Core 3.0 targets .NET Standard 1.1 but I am too far from my comfort zone there to be able to diagnostic anything.

So no PR. Instead, please find a largely untested Gist: https://gist.github.com/mcartoixa/8c001df6fec75cfa95ad33d693df8fc5. The VSTestForwardingApp and Tracing classes can be removed.

[mcartoixa]

Bump

[mcartoixa]

Anybody in there?

[nohwnd]

@pavelhorak we should do something about this but my plate is full right now. This imho needs a triage and might be affected by this change dotnet/sdk#11379.

@mcartoixa testing against a build of dotnet sdk takes a bit of effort. Based on where you need to do your changes you might be able to use a pre-build sdk installed via dotnet/installer and just patch the build task and point it to a difference vstestconsole dll using the VSTestConsolePath msbuild parameter.

Or you might need to build the whole dotnet/sdk and use their eng/dogfooding.cmd to start a powershell session with the correct env variables. There you can copy the correct task definition and also point it to the correct vstest console dll.

Copying the artifacts from vstest repo to the dotnet installation in fact does not work.

vstest/scripts/build.ps1

Line 269 in df61f73

function Publish-PatchedDotnet {

this is where I patch the task to be able to use a new one. This is only needed when you need to fix the .targets file itself.

You can override the path to the task dll and console dll by using those params:
https://github.com/microsoft/vstest/blob/master/src/Microsoft.TestPlatform.Build/Microsoft.TestPlatform.targets#L18-L19

Specified as:

dotnet test <path to csproj / sln> -p:VSTestConsolePath=<path to vstest.console.dll>

(Might be obvious, but let's point it out. this won't work with dotnet vstest or dotnet test + dll because those don't call msbuild.)

Hope this will help you investigate further.