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 #103279

[ViktorHofer]

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

[MihaZupan]

Random example:

runtime/src/libraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.cs

Line 4178 in f1f0750

public async Task ContentLength_DoesNotMatchRequestContentLength_Throws(int contentLength, int bytesSent)

.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),

runtime/eng/testing/xunit/xunit.runner.json

Line 2 in f8f4509

"diagnosticMessages": true,

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