Tests are spamming ITestOutputHelper logs for passing tests

[MihaZupan]

Tests that use ITestOutputHelper are now printing the output even when the test is passing. For example, if you run dotnet build .\src\libraries\System.Net.Http\tests\FunctionalTests\ /t:Test, the console will print 5000 lines of text even if everything's passing.

It looks like it started with #103279

[MihaZupan]

cc: @ViktorHofer this seems to have regressed with the Arcade update in https://github.com/dotnet/runtime/pull/103279

[ViktorHofer]

Can you please provide an example test that does this and an example console log?

[MihaZupan]

Random example: https://github.com/dotnet/runtime/blob/f1f075012af193948fa2d33e24adfbc8d92b8782/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs#L4178

.dotnet/dotnet build .\src\libraries\System.Net.Http\tests\FunctionalTests\ /t:Test /p:XUnitMethodName=System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws

PS C:\MihaZupan\runtime-debug-2> .dotnet/dotnet build .\src\libraries\System.Net.Http\tests\FunctionalTests\ /t:Test /p:XUnitMethodName=System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws

  Determining projects to restore...
  All projects are up-to-date for restore.
  TestUtilities -> C:\MihaZupan\runtime-debug-2\artifacts\bin\TestUtilities\Debug\net8.0\TestUtilities.dll
  ILLink.RoslynAnalyzer -> C:\MihaZupan\runtime-debug-2\artifacts\bin\ILLink.RoslynAnalyzer\Debug\netstandard2.0\ILLink.RoslynAnalyzer.dll
  ILLink.CodeFixProvider -> C:\MihaZupan\runtime-debug-2\artifacts\bin\ILLink.CodeFixProvider\Debug\netstandard2.0\ILLink.CodeFixProvider.dll
  ILCompiler.DependencyAnalysisFramework -> C:\MihaZupan\runtime-debug-2\artifacts\bin\ILCompiler.DependencyAnalysisFramework\Debug\ILCompiler.DependencyAnalysisFramework.dll
  Mono.Linker -> C:\MihaZupan\runtime-debug-2\artifacts\bin\Mono.Linker\ref\Debug\net9.0\illink.dll
  Mono.Linker -> C:\MihaZupan\runtime-debug-2\artifacts\bin\Mono.Linker\Debug\net9.0\illink.dll
  ILLink.Tasks -> C:\MihaZupan\runtime-debug-2\artifacts\bin\ILLink.Tasks\Debug\net9.0\ILLink.Tasks.dll
  System.DirectoryServices.Protocols -> C:\MihaZupan\runtime-debug-2\artifacts\bin\System.DirectoryServices.Protocols\ref\Debug\net9.0\System.DirectoryServices.Protocols.dll
  System.DirectoryServices.Protocols -> C:\MihaZupan\runtime-debug-2\artifacts\bin\System.DirectoryServices.Protocols\Debug\net9.0-windows\System.DirectoryServices.Protocols.dll
  StreamConformanceTests -> C:\MihaZupan\runtime-debug-2\artifacts\bin\StreamConformanceTests\Debug\net9.0\StreamConformanceTests.dll
  System.Net.Http.Functional.Tests -> C:\MihaZupan\runtime-debug-2\artifacts\bin\System.Net.Http.Functional.Tests\Debug\net9.0-windows\System.Net.Http.Functional.Tests.dll
  ========================= Begin custom configuration settings ==============================
  set __IsXUnitLogCheckerSupported=1
  ========================== End custom configuration settings ===============================
  ----- start Fri 06/14/2024 16:59:16.93 ===============  To repro directly: =====================================================
  pushd C:\MihaZupan\runtime-debug-2\artifacts\bin\System.Net.Http.Functional.Tests\Debug\net9.0-windows\
  "C:\MihaZupan\runtime-debug-2\artifacts\bin\testhost\net9.0-windows-Debug-x64\dotnet.exe" exec --runtimeconfig System.Net.Http.Functional.Tests.runtimeconfig.json --depsfile System.Net.Http.Functional.Tests.deps.json xunit.console.dll System.Net.Http.Functional.Tests.dll -xml testResults.xml -nologo -met
  hod System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws -notrait category=OuterLoop -notrait category=failing
  popd
  ===========================================================================================================
    Discovering: System.Net.Http.Functional.Tests (method display = ClassAndMethod, method display options = None)
    Discovered:  System.Net.Http.Functional.Tests (found 1 of 1791 test case)
    Starting:    System.Net.Http.Functional.Tests (parallel test collections = on [20 threads], stop on fail = off)
      System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws(contentLength: 0, bytesSent: 1) [PASS]
        Output:
          Ignored exception:
          System.IO.IOException: Got RST
             at System.Net.Test.Common.Http2LoopbackConnection.ReadBodyAsync(Boolean expectEndOfStream) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 588
             at System.Net.Test.Common.Http2LoopbackConnection.ReadAndParseRequestHeaderAsync(Boolean readBody) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 697
             at System.Net.Test.Common.Http2LoopbackConnection.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 981
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.<>c__DisplayClass1_0.<<ContentLength_DoesNotMatchRequestContentLength_Throws>b__1>d.MoveNext() in C:\MihaZupan\runtime-debug-2\src\libraries\System.Net.Http\tests\FunctionalTests\SocketsHttpHandlerTest.cs:line 4199
      System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws(contentLength: 1, bytesSent: 0) [PASS]
        Output:
          Ignored exception:
          System.IO.IOException: Got RST
             at System.Net.Test.Common.Http2LoopbackConnection.ReadBodyAsync(Boolean expectEndOfStream) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 588
             at System.Net.Test.Common.Http2LoopbackConnection.ReadAndParseRequestHeaderAsync(Boolean readBody) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 697
             at System.Net.Test.Common.Http2LoopbackConnection.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 981
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.<>c__DisplayClass1_0.<<ContentLength_DoesNotMatchRequestContentLength_Throws>b__1>d.MoveNext() in C:\MihaZupan\runtime-debug-2\src\libraries\System.Net.Http\tests\FunctionalTests\SocketsHttpHandlerTest.cs:line 4199
      System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws(contentLength: 1, bytesSent: 2) [PASS]
        Output:
          Ignored exception:
          System.IO.IOException: Got RST
             at System.Net.Test.Common.Http2LoopbackConnection.ReadBodyAsync(Boolean expectEndOfStream) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 588
             at System.Net.Test.Common.Http2LoopbackConnection.ReadAndParseRequestHeaderAsync(Boolean readBody) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 697
             at System.Net.Test.Common.Http2LoopbackConnection.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 981
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.<>c__DisplayClass1_0.<<ContentLength_DoesNotMatchRequestContentLength_Throws>b__1>d.MoveNext() in C:\MihaZupan\runtime-debug-2\src\libraries\System.Net.Http\tests\FunctionalTests\SocketsHttpHandlerTest.cs:line 4199
      System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest_Http2.ContentLength_DoesNotMatchRequestContentLength_Throws(contentLength: 2, bytesSent: 1) [PASS]
        Output:
          Ignored exception:
          System.IO.IOException: Got RST
             at System.Net.Test.Common.Http2LoopbackConnection.ReadBodyAsync(Boolean expectEndOfStream) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 588
             at System.Net.Test.Common.Http2LoopbackConnection.ReadAndParseRequestHeaderAsync(Boolean readBody) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 697
             at System.Net.Test.Common.Http2LoopbackConnection.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackConnection.cs:line 981
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Test.Common.Http2LoopbackServer.HandleRequestAsync(HttpStatusCode statusCode, IList`1 headers, String content) in C:\MihaZupan\runtime-debug-2\src\libraries\Common\tests\System\Net\Http\Http2LoopbackServer.cs:line 153
             at System.Net.Http.Functional.Tests.SocketsHttpHandler_RequestContentLengthMismatchTest.<>c__DisplayClass1_0.<<ContentLength_DoesNotMatchRequestContentLength_Throws>b__1>d.MoveNext() in C:\MihaZupan\runtime-debug-2\src\libraries\System.Net.Http\tests\FunctionalTests\SocketsHttpHandlerTest.cs:line 4199
    Finished:    System.Net.Http.Functional.Tests
  === TEST EXECUTION SUMMARY ===
     System.Net.Http.Functional.Tests  Total: 4, Errors: 0, Failed: 0, Skipped: 0, Time: 0.500s
  ----- end Fri 06/14/2024 16:59:18.34 ----- exit code 0 ----------------------------------------------------------

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

Time Elapsed 00:00:04.76

[ViktorHofer]

Tests that use ITestOutputHelper are now printing the output even when the test is passing.

That wasn't the case before? That sounds weird to me. cc @bradwilson (we recently upgraded to xunit 2.8.1)

[MihaZupan]

No, you'd only see the output for failing tests.

[bradwilson]

You shouldn't be seeing passing tests unless you're using the Verbose reporter.

Let me verify that something hasn't changed on our side.

[bradwilson]

Actually, I take it back. This is working as designed.

The code that you're hitting has been there since 2016. We print passing tests if both of these things are true:

• The test has output
• You have enabled diagnostic messages

It's likely the 2nd thing that's changed for you.

Here's an example:

[bradwilson]

(I didn't see it on your provided command line, so I assumed it's been enabled in an xunit.runner.json file in the source tree.)

[MihaZupan]

Setting diagnosticMessages to false does bring back the previous behavior (not printing output for passing tests), https://github.com/dotnet/runtime/blob/f8f450953d71dabe3fd01961c1d05b57c61e8faf/eng/testing/xunit/xunit.runner.json#L2

but this configuration also hasn't changed over the last 5 years 😕

[bradwilson]

this configuration also hasn't changed over the last 5 years

Maybe the file wasn't being copied properly and thus never being used? Is it possible that that's a fix that went in recently?

[MihaZupan]

Interestingly, other diagnostic info (e.g. how many tests were discovered) has been shown before, so it seems like the config was being honored. That disappears if I just toggle that config to false.

[bradwilson]

That output is coming from our default reporter. Maybe you were running with a different reporter? What is the context where you're seeing this? We have several environmentally enabled reporters (mostly for CI environments like AppVeyor, TeamCity, and VSTS/Azure Pipelines).

[MihaZupan]

Local run from a console on Windows

[bradwilson]

I tried rolling back to both the 2.4.2 framework and 2.4.2 runners, and I can still reproduce the behavior:

I am honestly perplexed about what's changed in your environment.

[MihaZupan]

@bradwilson I was able to narrow it down to a change in xunit.runner.utility.netcoreapp10.dll between 2.8.0 and 2.8.1. (replacing the assembly from a https://www.nuget.org/packages/xunit.runner.utility/2.8.0 package makes it behave like before)

Looking at the xUnit repo, I only see 4 commits there: https://github.com/xunit/xunit/commit/ed625e5ec35dabae1d485d22e107203f112a7786, https://github.com/xunit/xunit/commit/bef8ac4634ae9eb94c376883b6c06c264585e130, https://github.com/xunit/xunit/commit/c2f2d47ec00d1dfc408bacced12f96647a2f695f, https://github.com/xunit/xunit/commit/f497d65ec5b3f7780d1f7034b2725d40da31daea Does that ring any bells?

[bradwilson]

It could very well be this: https://github.com/xunit/xunit/commit/f497d65ec5b3f7780d1f7034b2725d40da31daea

But the point remains: this is still working as designed. The fact that it might've been previously broken in some scenarios and gotten fixed in the meantime won't change that fact. I'm not going to re-break the library by rolling back this fix for other issues.

[MihaZupan]

@ViktorHofer do you see an issue if we toggle the diagnosticMessages off? https://github.com/dotnet/runtime/blob/f8f450953d71dabe3fd01961c1d05b57c61e8faf/eng/testing/xunit/xunit.runner.json#L2

As-is, the console output is a lot less useful -- example in #103703 where logs are just a red herring.

[ViktorHofer]

Diagnostic messages got enabled to enable long running test logging.

[ManickaP]

@ViktorHofer do you have any suggestions how to make this work for both sides? How should we log from the tests so that we don't spam the output in case the test is successful? We can change our code, but I'd prefer not to remove all the logging we have put in.

[ViktorHofer]

I'm not sure that I'm the right person to answer this question. According to Brad it sounds like using ITestOutputHelper always logs, even in the success case and that previous behavior in runtime was just a glitch. @bradwilson I assume there isn't a log level lower than diagnostic messages so that long running tests still get logged but other stuff doesn't?

[bradwilson]

I assume there isn't a log level lower than diagnostic messages so that long running tests still get logged but other stuff doesn't?

There is not. The intention with diagnostic messages was that people would turn them on while they had a problem, to help them figure the problem out, then turn them back off.

My suggestion in this scenario would be to turn them off by default, so that your normal interactive usage would not be overwhelmed with the test output, and then you can temporarily turn them on when debugging issues. You could turn them for non-interactive builds like CI builds, since I presume that the output there would primarily be ignored if the tests were passing.

[ViktorHofer]

Thanks Brad. For us it's important to have long running tests logged in CI so we need diagnostic messages there. Having that turned off locally only sounds like a possible option.

[bradwilson]

You should be able to use environment variables to detect running in CI, and then use command line switches to override the configuration file. If you're directly using our command line runner, then it would be -diagnostics; if you're using VSTest via something like dotnet test, then you could add -- xUnit.DiagnosticMessages=true to modify the RunSettings.

More information on RunSettings: https://xunit.net/docs/runsettings

[MihaZupan]

While definitely an improvement if it worked locally, this also isn't great in CI. E.g. this is what a successful test run with no failures looks like: console logs Or example from https://github.com/dotnet/runtime/issues/103703#issuecomment-2178940706 where a crash was misreported as a test failure because the logs are misleading.

[ManickaP]

it's important to have long running tests logged in CI

Is there a difference in behavior of logging in CI and locally? Because long running tests do not produce output locally. AFAICT, the logs are printed after the test finishes, not during. And in case of long running tests / hangs, the process needs to be killed so there's not even testResults.xml.

[ViktorHofer]

See https://github.com/dotnet/runtime/issues/103265 for an example of how long running tests are logged in CI. AFAIK there's no difference in logging between CI and a local run.

[ManickaP]

But that's not the output from the test, AFAICS none of these tests from your example log anything to ITestOutputHelper. That's XUnit itself informing that it detected long running test.

[ViktorHofer]

Correct, we need xunit to tell us which tests are long running. And AFAIK xunit needs to have diagnostic messages enabled for that. Was I saying something different?

it's important to have long running tests logged in CI

With that statement I meant that it's important that xunit logs which tests are long running not that it's important that long running tests log their own output.

[ManickaP]

I see, my bad. I didn't realize XUnit doesn't differentiate those types of messages and won't print long running tests info if the logging is off (I should have read the whole discussion with more care), that's a shame.

One more thing though:

You could turn them for non-interactive builds like CI builds, since I presume that the output there would primarily be ignored if the tests were passing.

This logic has a small problem. In case there is a failing test, the output is still spammed with all the passing tests, so it's much harder now to find the relevant text. Leading to badly filed build-analysis issues, e.g.: look at this issue description history https://github.com/dotnet/runtime/issues/103482

[bradwilson]

If you insist on (a) having every test logging a ton, and (b) turning on diagnostic messages for long running test detection, there is no way today to separate the two situations.

I only have one other suggestion, which is probably not going to be helpful, but I thought I'd throw it out there anyways: have you considered not having your tests logging a ton of information all the time, and only turning it on when you're trying to debug a problem?

[ManickaP]

there is no way today to separate the two situations.

Would you be open to the idea of changing that? Separating the "long running test" messages into higher severity? We would be open to contribute that change if you'd be willing to accept it.

Edit: ping @bradwilson

[bradwilson]

I haven't had the time yet to plan out an appropriate design, though I will get to it.

[bradwilson]

Here's what my plan is.

1. For v2 (with a release pending shortly) I'm going to give you an environment variable that you can set which will turn off showing output from passing tests. You can set this in your build scripts for both interactive and CI builds. I will forward-port this to v3.

2. For v3, additionally I'm going to move long running test messages to their own category of message, so that enabling long running test detection does not require enabling diagnostic messages. This is the strategy I think probably fits best for you long term, though the environment variable option will still be present if you opt to keep diagnostic messages enabled.

[bradwilson]

This is now available in v2 2.8.2-pre.20 https://xunit.net/docs/using-ci-builds

You can set XUNIT_HIDE_PASSING_OUTPUT_DIAGNOSTICS to any non-empty value and it will hide the passing tests with output from being shown. If the value is empty or missing, then the default behavior will be used.

I am planning to ship a new v2 release in the next few days, depending on how far behind I currently am on issues and pull requests after being heads down for 3 weeks working on v3.

[bradwilson]

I've also opened a discussion issue to understand how widespread the problem is, to decide whether we should also enable this behavioral switch via a configuration file item. Feel free to add your feedback there: https://github.com/xunit/xunit/discussions/2969

[ViktorHofer]

Perfect. We will update to 2.8.2 when it is stable as we are close to RC1 which requires stable package dependencies (a few of our packages depend on xunit). Thanks for your help, Brad 👍

[bradwilson]

~We have final RTM packages available on our CI server, but NuGet is rejecting them because of a certificate change. I have no idea when this will be resolved.~

[bradwilson]

The packages are uploaded to NuGet.org now, and I'm just waiting for the xunit.net site deployment to make the announcement.

[bradwilson]

https://dotnet.social/@xunit/112752046346372524

[ViktorHofer]

This needed https://github.com/dotnet/arcade/pull/14930 which is now merged. We are still waiting for dependency flow to bring this change into runtime though: https://github.com/dotnet/runtime/pull/105301

[ViktorHofer]

After the above dependency flow PR is merged the env var will need to be set. I assume that the RunTests.cmd/sh scripts are the right place for xunit.console and the runsettings.targets file for dotnet test.

[ViktorHofer]

https://github.com/dotnet/runtime/pull/105392 should fix this. @MihaZupan would you mind trying it out?

[bradwilson]

🎉

[ViktorHofer]

Thanks a lot for your help, Brad 👍

[bradwilson]

Glad we could find a good workaround for you!