[Build] Console output lost

[ManickaP]

After update to the newest tools, the output from msbuild has changed and now auto-updates an existing line in terminal instead of printing all output out. As a result, the important information about failing tests is lost and this is what remains:

dotnet build tests/FunctionalTests/ -t:test
MSBuild version 17.10.0-preview-24060-03+1725b247e for .NET
Restore complete (2.6s)
  TestUtilities net8.0 succeeded (4.2s) → /home/manicka/repositories/runtime/artifacts/bin/TestUtilities/Debug/net8.0/TestUtilities.dll
  System.Net.Quic.Functional.Tests net9.0-linux failed with errors (30.3s) → /home/manicka/repositories/runtime/artifacts/bin/System.Net.Quic.Functional.Tests/Debug/net9.0-linux/System.Net.Quic.Functional.Tests.dll
    /home/manicka/repositories/runtime/eng/testing/tests.targets(195,5): error : One or more tests failed while running tests from 'System.Net.Quic.Functional.Tests'. [/home/manicka/repositories/runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/System.Net.Quic.Functional.Tests.csproj]

Build failed with errors in 40.1s

No failing test name, no failure details, no clickable link to testResults.xml.

I do not know if this is an issue in our infra (the way we call msbuild) or arcade or msbuild itself, so feel free to transfer this issue.

Tagging subscribers to this area: @dotnet/runtime-infrastructure
See info in area-owners.md if you want to be subscribed.

Issue Details

---

After update to the newest tools, the output from msbuild has changed and now auto-updates an existing line in terminal instead of printing all output out. As a result, the important information about failing tests is lost and this is what remains:

dotnet build tests/FunctionalTests/ -t:test
MSBuild version 17.10.0-preview-24060-03+1725b247e for .NET
Restore complete (2.6s)
  TestUtilities net8.0 succeeded (4.2s) → /home/manicka/repositories/runtime/artifacts/bin/TestUtilities/Debug/net8.0/TestUtilities.dll
  System.Net.Quic.Functional.Tests net9.0-linux failed with errors (30.3s) → /home/manicka/repositories/runtime/artifacts/bin/System.Net.Quic.Functional.Tests/Debug/net9.0-linux/System.Net.Quic.Functional.Tests.dll
    /home/manicka/repositories/runtime/eng/testing/tests.targets(195,5): error : One or more tests failed while running tests from 'System.Net.Quic.Functional.Tests'. [/home/manicka/repositories/runtime/src/libraries/System.Net.Quic/tests/FunctionalTests/System.Net.Quic.Functional.Tests.csproj]

Build failed with errors in 40.1s

No failing test name, no failure details, no clickable link to testResults.xml.

I do not know if this is an issue in our infra (the way we call msbuild) or arcade or msbuild itself, so feel free to transfer this issue.

Author:	ManickaP
Assignees:	-
Labels:	area-Infrastructure, untriaged, needs-area-label
Milestone:	-

[akoeplinger]

That's the new msbuild terminal logger (dotnet/sdk#37492), you can disable it via -tl:false.

Looks like there are some improvements coming for dotnet test as well: dotnet/sdk#38098.
I'm not sure though if that will automatically apply to our infrastructure. Maybe we should disable the terminal logger for the test target for now. @ViktorHofer

[stephentoub]

Maybe we should disable the terminal logger for the test target for now.

Yes, please. I just got bit by this as well.

Why is not showing the test failures a better experience, @rainersigwald?

[rainersigwald]

Local workaround

Set the environment variable DOTNET_CLI_CONFIGURE_MSBUILD_TERMINAL_LOGGER=false which will opt out of the new logger.

Committable workaround

Maybe we should disable the terminal logger for the test target for now.

You can't do this within MSBuild based on requested target; you'll need to disable -tl entirely (easiest way would be to put -tl:false in a root Directory.Build.rsp).

Ok but what's going on?

I'm not sure though if that will automatically apply to our infrastructure.

They would not, the critical change there is what logging/warning/error APIs the task running the tests calls, and Arcade tests do that all manually.

Why is not showing the test failures a better experience, @rainersigwald?

It isn't. What happened is that build output is so polluted by "high" priority messages that the terminal logger mostly disregards them. Here, it sounds like all of the debugging test output is given in a message, rather than in the error, which combines badly with that.

The plan for dotnet test is that the test runner task will switch to using MSBuild logging rather than directly emitting to stdout, and we're planning to add logging APIs to allow test to produce a nicely formatted summary message (like they do today by bypassing MSBuild, but not lost to logs and multiproc-compatible).

It should be possible to change the repo/Arcade test infrastructure to provide more details in a way that is more MSBuild-y. I'll take a look.

cc @baronfel, @rokonec

[rainersigwald]

There's already logic that tries to include the TRX in the failure message, which works for me when I artificially induce a failure in STJ tests.

runtime/eng/testing/tests.targets

Lines 189 to 195 in 5a6135e

	<PropertyGroup Condition="'$(TestRunExitCode)' != '0'">
	<TestResultsPath>$(OutputPath)$(TestResultsName)</TestResultsPath>
	<TestRunErrorMessage>One or more tests failed while running tests from '$(TestProjectName)'.</TestRunErrorMessage>
	<TestRunErrorMessage Condition="Exists('$(TestResultsPath)')">$(TestRunErrorMessage) Please check $(TestResultsPath) for details!</TestRunErrorMessage>
	</PropertyGroup>
	<Error Condition="'$(TestRunExitCode)' != '0'" Text="$(TestRunErrorMessage)" />

❯ dotnet build -t:test -bl
MSBuild version 17.10.0-preview-24060-03+1725b247e for .NET
Restore complete (1.0s)
...
  System.Text.Json net462 succeeded (0.7s) → S:\runtime\artifacts\bin\System.Text.Json\Debug\net462\System.Text.Json.dll
  System.Text.Json.Tests net462 failed with errors (1.4s) → S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\System.Text.Json.Tests.dll
    S:\runtime\eng\testing\tests.targets(195,5): error : One or more tests failed while running tests from 'System.Text.Json.Tests'. Please check S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\testResults.xml for details! [S:\runtime\src\libraries\System.Text.Json\tests\System.Text.Json.Tests\System.Text.Json.Tests.csproj]

Build failed with errors in 8.4s

I don't know why that didn't trigger for you, @ManickaP.

Of course, that's still less data than the super verbose dump you had before

  System.Text.Json -> S:\runtime\artifacts\bin\System.Text.Json\Debug\net462\System.Text.Json.dll
  System.Text.Json.Tests -> S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\System.Text.Json.Tests.dll
  ========================= Begin custom configuration settings ==============================
  ========================== End custom configuration settings ===============================
  ----- start Fri 01/19/2024 11:46:27.91 ===============  To repro directly: ==========================================
  ===========
  pushd S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\
  xunit.console.exe System.Text.Json.Tests.dll -xml testResults.xml -nologo -notrait category=OuterLoop -notrait catego
  ry=failing
  popd
  ===========================================================================================================
    Discovering: System.Text.Json.Tests (app domain = on [no shadow copy], method display = ClassAndMethod, method disp
  lay options = None)
    Discovered:  System.Text.Json.Tests (found 9 test cases)
    Starting:    System.Text.Json.Tests (parallel test collections = on, max threads = 32)
      System.Text.Json.Tests.JsonElementCloneTests.CloneTwiceFromSameDocument [FAIL]
        Assert.True() Failure
        Expected: True
        Actual:   False
        Stack Trace:
          S:\runtime\src\libraries\System.Text.Json\tests\System.Text.Json.Tests\JsonElementCloneTests.cs(14,0): at Sys
  tem.Text.Json.Tests.JsonElementCloneTests.CloneTwiceFromSameDocument()
    Finished:    System.Text.Json.Tests
  === TEST EXECUTION SUMMARY ===
     System.Text.Json.Tests  Total: 9, Errors: 0, Failed: 1, Skipped: 0, Time: 0.180s
  ----- end Fri 01/19/2024 11:46:28.41 ----- exit code 1 ----------------------------------------------------------
S:\runtime\eng\testing\tests.targets(195,5): error : One or more tests failed while running tests from 'System.Text.Jso
n.Tests'. Please check S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\testResults.xml for details! [S:\ru
ntime\src\libraries\System.Text.Json\tests\System.Text.Json.Tests\System.Text.Json.Tests.csproj::TargetFramework=net462
]

Build FAILED.

Trying to see if we can conditionally emit that on test failure.

[stephentoub]

I don't know why that didn't trigger for you

It says that there are errors, but not what those errors are. That's my problem. To actually see the errors I then need to go load up the XML file from xunit and search through it looking for what went wrong.

[stephentoub]

I'll take a look.

Thanks!

[rainersigwald]

How would y'all feel about this?

text version

  System.Text.Json net462 succeeded (0.1s) → S:\runtime\artifacts\bin\System.Text.Json\ref\Debug\net462\System.Text.Json.dll
  System.Text.Json net462 succeeded (0.9s) → S:\runtime\artifacts\bin\System.Text.Json\Debug\net462\System.Text.Json.dll
--interactive test output, because a test failed--
========================= Begin custom configuration settings ==============================
========================== End custom configuration settings ===============================
----- start Fri 01/19/2024 13:44:41.68 ===============  To repro directly: =====================================================
pushd S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\
xunit.console.exe System.Text.Json.Tests.dll -xml testResults.xml -nologo -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================
Discovering: System.Text.Json.Tests (app domain = on [no shadow copy], method display = ClassAndMethod, method display options = None)
Discovered:  System.Text.Json.Tests (found 9 test cases)
Starting:    System.Text.Json.Tests (parallel test collections = on, max threads = 32)
System.Text.Json.Tests.JsonElementCloneTests.CloneTwiceFromSameDocument [FAIL]
Assert.True() Failure
Expected: True
Actual:   False
Stack Trace:
S:\runtime\src\libraries\System.Text.Json\tests\System.Text.Json.Tests\JsonElementCloneTests.cs(14,0): at System.Text.Json.Tests.JsonElementCloneTests.CloneTwiceFromSameDocument()
Finished:    System.Text.Json.Tests
=== TEST EXECUTION SUMMARY ===
System.Text.Json.Tests  Total: 9, Errors: 0, Failed: 1, Skipped: 0, Time: 0.188s
----- end Fri 01/19/2024 13:44:42.26 ----- exit code 1 ----------------------------------------------------------
  System.Text.Json.Tests net462 failed with errors (1.9s) → S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\System.Text.Json.Tests.dll
    S:\runtime\eng\testing\tests.targets(199,5): error : One or more tests failed while running tests from 'System.Text.Json.Tests'. Please check S:\runtime\artifacts\bin\System.Text.Json.Tests\Debug\net462\testResults.xml for details! [S:\runtime\src\libraries\System.Text.Json\tests\System.Text.Json.Tests\System.Text.Json.Tests.csproj]

Build failed with errors in 17.4s

It loses the leading whitespace (dotnet/msbuild#9668) but is fairly close to the prior output and can be done with a small patch in this repo (15c21fe).

[wfurt]

It says that there are errors, but not what those errors are. That's my problem. To actually see the errors I then need to go load up the XML file from xunit and search through it looking for what went wrong.

note that CI test runs do not preserver the XML any more AFAIK. e.g. the console output is only once clue we have in many cases.