Tests are spamming ITestOutputHelper logs for passing tests

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

@ViktorHofer

cc: @ViktorHofer this seems to have regressed with the Arcade update in #103279

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

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

@bradwilson

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)

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

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.

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:

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

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 😕

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?

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.

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

Local run from a console on Windows

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

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.

Set xunit env var to not print output for passing tests

@MihaZupan

#105392 should fix this. @MihaZupan would you mind trying it out?

Set xunit env var to not print output for passing tests (dotnet#105392)

🎉

Thanks a lot for your help, Brad 👍

Glad we could find a good workaround for you!

Set xunit env var to not print output for passing tests (#105392)

Remove support for older LLVM versions, and re-order linker flags (#1…

Navigation Menu

Repository navigation

Tests are spamming ITestOutputHelper logs for passing tests #103445

31 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Tests are spamming ITestOutputHelper logs for passing tests #103445

Description

Activity

MihaZupan commented on Jun 13, 2024

ViktorHofer commented on Jun 14, 2024

MihaZupan commented on Jun 14, 2024

ViktorHofer commented on Jun 14, 2024

MihaZupan commented on Jun 14, 2024

bradwilson commented on Jun 14, 2024

bradwilson commented on Jun 14, 2024

bradwilson commented on Jun 14, 2024

MihaZupan commented on Jun 14, 2024

bradwilson commented on Jun 14, 2024

MihaZupan commented on Jun 14, 2024

bradwilson commented on Jun 14, 2024

MihaZupan commented on Jun 14, 2024

31 remaining items

ViktorHofer commented on Jul 18, 2024

ViktorHofer commented on Jul 18, 2024

ViktorHofer commented on Jul 24, 2024

bradwilson commented on Jul 25, 2024

ViktorHofer commented on Jul 25, 2024

bradwilson commented on Jul 25, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions