Better fix for MSBuild task failed but did not log an error

[KirillOsenkov]

@nohwnd I'm looking at this PR:
#2557

Currently the problem I'm seeing in #2952 is this output from MSBuild:

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

This is because the test host crashed, but we don't have any further info.

We should never, ever, ever see this output from MSBuild. The MSBuild team added the check to prevent this that #2557 is disabling using reflection.

I'm thinking of another way of fixing this, which is check the result that we're about to return, and if we're returning false, log an error always. Or find a way to thread through the error to the VSTestTask and log it properly. But just in case I'd always log even a dummy error such as "Test run failed", to ensure that MSBuild doesn't fail but report 0 errors.

[nohwnd]

@KirillOsenkov disabling it like that was a recommendation from MSBuild team (Rainer), because test platform is reporting all it's errors to screen and not into msbuild. The other alternative was that we reported an error, but the whole build failed with "Error was not reported" from MSBuild. So it did not add any extra info and terminated pipelines that would otherwise continue to "upload test results step".

I know that reporting errors to screen while you are running inside of MSBuild is wrong, but that is how it was done till now. I am actually looking into how and if we could make MSBuild more of and implementation detail, because it seems that it was just a simple way to get a) the platform and dll path info, b) getting paralellism. But it causes a lot of problems for us. 1) we don't integrate well with msbuild, as you can see. 2) we cannot use node reuse, because we are writing to screen. 3) the processes that msbuild starts, are all writing to screen but are not communicating with each other, so you don't see aggregated results ( e.g. total test count from all assemblies). 4) they can cause deadlocks in some consoles (this was mostly fixed by MSBuild imho).

We probably can easily write error to msbuild stream but, it would be reported twice, so I would like to consider the overall picture before doing yet another quick fix. In which scenario are you seeing this problem, in a normal azure devops run, using the standard tasks, or are you integrating it with something else? Feel free to ping me on teams as well if that is better :)

[KirillOsenkov]

See related question here:
https://stackoverflow.com/questions/68043052/how-to-surface-unit-test-failure-messages-as-build-errors-in-net-core#

I'm guessing what folks want is more integration with MSBuild, not less.

FYI @MarkKharitonov

[MarkKharitonov]

It does not have to be tight integration. We could have something like Exec's CustomErrorRegularExpression and CustomWarningRegularExpression. Suppose msbuild recognized these as build properties. Then we could call dotnet test like this:

dotnet test -p:CustomErrorRegularExpression=....

And that would cause msbuild to augment its default error message recognition with the given regex.

This is how our ad-hoc testing worked - we invoked a custom script from an Exec task invoked after build. This Exec task was given CustomErrorRegularExpression and it was all hunky-dory - enough of unit test failure message was recognized by msbuild as an error and was therefore surfaced to the PR build summary page.

However, we wanted to be standard. So we dumped the ad hoc code and adopted the DotNetCoreCLI@2 task which delegates directly to dotnet, in this case dotnet test. And suddenly the errors disappeared from the build summary page. True, they appear in the log and in the Test tab of the build, but not the build summary.

[KirillOsenkov]

FYI @AArnott who has been investigating this recently

[nohwnd]

Would this help #2702 ? We need to test that, and change VSTestUseConsole = True to keep the current behavior, but you could override it.

[KirillOsenkov]

That PR still uses Reflection to mess with the build engine. We really should rely on MSBuild logging exclusively, and not write anything to the Console.

[mcartoixa]

@KirillOsenkov Agreed, and that is actually what #2702 does, but the current behavior (and code) has been kept for compatibility purposes (though in a somewhat obtuse way: the new code is in the old file and the old code is in a new file...).

It seemed to me like the easiest way forward that would not break anything. dotnet test will work as today (with colored output) and launching tests with MSBuild will work as MSBuild users expect (including less fancy coloring).

From this point I believe that a long term fix would be to:

• find a way to make dotnet test independent of MSBuild and call dotnet vstest.console.dll directly. But MSBuild would have to be called too if we want the tests to build automatically prior to launching the tests so this might be somewhat tricky.
• get rid of the (now) legacy tricks around MSBuild.

[MarkKharitonov]

Guys, please help me understand what is the right forum to discuss the problem of surfacing errors in a pipeline. There nobody cares about colors. But we do care about the error reported on the build page, i.e. the test output be recognized by msbuild and parsed to extract error messages. And if the failing test output is not recognized as errors - we need a way to help msbuild to recognize them. Finally, we want to use standard tooling that comes with Azure DevOps, we do not want to write ad hoc scripts. So, who is the right address here? The current situation is nonsense - Microsoft own offerings do not integrate with each other. This is really frustrating.

[Sanan07]

@MarkKharitonov I am not fully sure, but you can try to write to these repos and maybe they will point you to correct repo or people
https://github.com/microsoft/azure-pipelines-agent
https://github.com/microsoft/azure-pipelines-tasks

[nohwnd]

@MarkKharitonov it does integrate via TRX reports and uploading test results. Which is even done for you automatically if you use the VSTest task.

[MarkKharitonov]

@nohwnd - that is correct. But it does not surface the test errors on the build summary page. We use the standard DotNetCoreCLI@2 task with the test keyword. It invokes dotnet test and then uploads the trx and integrates with the build - correct. But it is important to see meaningful build errors on the summary page too, rather than the dull dotnet.exe returned exit code 1 (or something like that).

Why is that?

1. We have 300+ developers. It is impossible to explain to everyone that some errors need to be looked up in the Test tab.
2. We have build observability data collection. It includes all kinds of metrics, including the build errors. We use the Azure DevOps REST API to collect these and whatever is not on the build summary page is not available. Simply because the reason for them not being on the build summary page is because msbuild does not consider them as error messages.

@Sanan07 - what would I ask there? We use the standard tasks which invoke the dotnet executable. The problem is that errors reported from dotnet test are not errors from msbuild perspective. And consequently they are not errors from the CI/PR build perspective.

I cannot help but wonder. I see discussion about yes colors, no colors. For some reason no one is bothered by the lack of proper error reporting in Microsoft's pipeline offering. I would like to emphasize it again - Surfacing the errors in the Test tab is not enough.

[KirillOsenkov]

@MarkKharitonov I am sympathetic, if that helps. I also think that since dotnet test is using MSBuild, it should be emitting proper MSBuild BuildEventArgs objects (such as BuildMessageEventArgs, BuildWarningEventArgs, BuildErrorEventArgs) instead of opaque logging. In fact, #2702 is a community contribution that introduces a better MSBuild task that we could further shape into doing the right thing MSBuild-wise.

Things are not set in stone and are still in flux. We're trying to make things better. It takes time. Discussions and feedback like these are valuable and are helping to steer the team in the right direction. @nohwnd is really helpful and really wants to improve the system for all of us. It's just we're dealing with legacy and poor design decisions that will take a while to properly clean up.

[KirillOsenkov]

An extra benefit of emitting better MSBuild logging is that you'll see all of this in the .binlog as well, so you could using the binlog viewer to see the things that happened and dig deeper (instead of reading text output).

[nohwnd]

Fixed in #2702 and the subsequent terminal logger work.