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.

[mcartoixa]

@nohwnd Thanks for the ❤️!

If I remember correctly the only fix is to base the task on ToolTask which takes care of the logging (and is the right thing to do anyway). I will try and set up a test environment for my fix. I am much more experienced in MSBuild than in PRs though: do you want a PR based on the current master?

[mcartoixa]

@nohwnd FYI I have just got bitten hard by a strange (?) behavior: I've got to quite some trouble to customize VSTestTaskAssemblyFile and VSTestTargets to my locally built files and VSTestConsolePath to the SDK file. Trouble was: all my changes seemed to be taken into account in the logs, but I couldn't see any change in the behavior of the task... Even having the task throwing random exceptions: the build behaved the same. I finally changed the name of the task to VSTestTask2 and got an error MSB4062 (I suspect .NET Standard 2.0 but I will invetigate further).

In short, it seems that UsingTask can silently revert to a task it can somehow find in the current environment if the one you specify cannot be loaded... I'll try and file a bug when I have time.

[mcartoixa]

It seems we have a problem with PR #2437 because:

• MSBuild (and at this point the whole runtime it would seem, cf. Implement a way to enable color in console even when the output is redirected dotnet/runtime#33980) does not support custom tool colorization (cf. Exec ConsoleToMSBuild=true doesn't preserve colors dotnet/msbuild#4299), by design IMHO.
• dotnet test requires custom colorization of the output, but is based on MSBuild. So in the current code MSBuild is bypassed which allows for the requirement but prevents the logging of the output...

I know I am very late to this game and that there are complexities involved that I do not understand but if you would indulge me for a bit anyway my suggestion would be:

• The PR makes VSTest works nice in the context of MSBuild. No custom colorization (by design) but errors are reported in full red (which is standard in MSBuild and would address the primary concern of Support Colorized Output in GitHub Actions #2370 btw) and logs are functional. If you want this behavior, use dotnet msbuild.
• If you want custom colorization (and possibly other features) use dotnet test, which should not depend on MSBuild. In fact, as noted elsewhere, dotnet test currently calls MSBuild which itself calls dotnet exec vstest.console.dll so it's just a matter of cutting the middle man there.

I believe achieving this would give a more consistent experience, and give more choice to developers. But:

• It would delay the fixing of this bug by quite a lot. Not a problem as it is 3 years old already and better late than never.
• From what I can gather the main difficulty would be to do what MSBuild currently does in the context of dotnet test: gathering test project file paths (in TestFileFullPath). I am sure there is a way around that (one idea would be to call a transient MSBuild process just to perform this task).

Let me know what you think. I may be of help if I can (and if you are interested).

[mcartoixa]

Slow days at work, so here what I intend to do:

• submit a PR to the dotnet/sdk project so that dotnet test (and dotnet vstest) rely directly on the execution of dotnet exec vstest.console.dll instead of going through MSBuild. This will (amongst other things) ensure that these commands will be able to retain the colored output of the original, which should please regular console users.
• then submit again a PR to this project to essentially do again what I did last year (cf. Reimplement the MSBuild VSTestTask task based on ToolTask #2437). MSBuild will lose the coloured input of the original but will gain the ability to log properly, and report warnings and errors consistently with the rest of the MSBuild ecosystem. MSBuild users (AppVeyor, Visual Studio or me) do not care much for fancy colors, but they would very much expect errors to appear in red in their output...
  I am hopeful (for now) that maybe this bug (and at least VSTest is printing using Console.WriteLine instead of using the logger #2224) won't survive 2021.

[mcartoixa]

This bug is nearly 5 years old now. Its root causes have metastasized bugs in different repositories (#1503, #2224, #2953, dotnet/msbuild#5387, dotnet/sdk#9481 are some could gather). #2702 should help clean the whole thing up but is more than a whole year old at this point.

What would be nice would be some sense of visibility about the future. Is a fix going to make its way in 2022? .NET 8 perhaps?

[mcartoixa]

I am still struggling with this, years later. Tests work fine on machine but fail on the CI server. Check the logs:

     7>Done building target "ShowCallOfVSTestTaskWithParameter" in project "FlightBoard.Api.V1.Tests.csproj".
       Done executing task "CallTarget".
       Using "Microsoft.TestPlatform.Build.Tasks.VSTestTask" task from assembly "C:\Program Files\dotnet\sdk\6.0.300\Microsoft.TestPlatform.Build.dll".
       Task "Microsoft.TestPlatform.Build.Tasks.VSTestTask"
       Done executing task "Microsoft.TestPlatform.Build.Tasks.VSTestTask" -- FAILED.
   1:7>Done executing task "MSBuild" -- FAILED.
   1:7>Done building target "TestProject" in project "FlightBoard.Api.proj" -- FAILED.
     7>Done building target "VSTest" in project "FlightBoard.Api.V1.Tests.csproj" -- FAILED.

Thanks for nothing, and good luck with that.

The most frustrating thing is to know that there has been a fix waiting in the limbo for the last 18 months (#2702).
Is it reasonable to hope for an update on the status of this bug at some point? (cc @nohwnd)

[nohwnd]

This was addressed in #2702