[browser] reduce System.Net.WebSockets.Client.Tests noise in log files #97654

pavelsavara · 2024-01-29T16:52:37Z

No description provided.

ghost · 2024-01-29T16:52:47Z

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

Issue Details

null

Author:	pavelsavara
Assignees:	pavelsavara
Labels:	`area-System.Net.Http`
Milestone:	9.0.0

MihaZupan · 2024-01-29T21:40:48Z

What is the motivation behind the change here? As far as I understand these logs should only be visible if the test fails.

stephentoub · 2024-01-30T02:28:28Z

src/libraries/System.Net.WebSockets.Client/tests/ClientWebSocketOptionsTests.cs

@@ -72,12 +72,9 @@ public async Task Proxy_ConnectThruProxy_Success(Uri server)
            string proxyServerUri = System.Net.Test.Common.Configuration.WebSockets.ProxyServerUri;
            if (string.IsNullOrEmpty(proxyServerUri))
            {
-                _output.WriteLine("Skipping test...no proxy server defined.");


This should probably instead be throw new SkipTestException("No proxy server defined.");

pavelsavara · 2024-01-30T11:44:07Z

What is the motivation behind the change here? As far as I understand these logs should only be visible if the test fails.

That's interesting. I thought I saw them unexpected in some console log on the WASM platform.
But I can't find nor replicate it anymore.

pavelsavara · 2024-01-30T12:00:11Z

I found it Log
Build https://dev.azure.com/dnceng-public/public/_build/results?buildId=545570&view=logs&jobId=3087b8b9-b9da-5b2b-e6fa-b58c34928353

[09:07:01] info: 	[STRT] System.Net.WebSockets.Client.Tests.HttpClientCloseTest.CloseAsync_ServerInitiatedClose_Success(server: ws://127.0.0.1:36481/WebSocket/EchoWebSocket.ashx, useCloseOutputAsync: False)
[09:07:01] info: GetConnectedWebSocket: ConnectAsync starting.
[09:07:01] info: 
[09:07:01] info: GetConnectedWebSocket: ConnectAsync done.
[09:07:01] info: 
[09:07:01] info: SendAsync starting.
[09:07:01] info: 
[09:07:01] info: SendAsync done.
[09:07:01] info: 
[09:07:01] info: ReceiveAsync starting.
[09:07:01] info: 
[09:07:01] info: ReceiveAsync done.
[09:07:01] info: 
[09:07:01] info: Close starting.
[09:07:01] info: 
[09:07:01] info: Close done.
[09:07:01] info: 
[09:07:01] info: 	[PASS] System.Net.WebSockets.Client.Tests.HttpClientCloseTest.CloseAsync_ServerInitiatedClose_Success

CarnaViire · 2024-01-30T12:20:31Z

It seems like the logs (for that PR? or for wasm in general?) are set up to be more verbose than they should normally be, i.e. every test there -- including passing ones -- prints at least 2 lines (on start and on finish). That is not the case for coreclr test logs, which only outputs failed tests.

Compare the below from the WasmTestOnBrowser log you've linked:

pushd .
if [[ WasmTestOnBrowser == WasmTestOnNodeJS || WasmTestOnBrowser == wasmtestonnodejs ]]
then npm ci
fi
dotnet exec /root/helix/work/correlation/microsoft.dotnet.xharness.cli/9.0.0-prerelease.24077.1/tools/net8.0/any/Microsoft.DotNet.XHarness.CLI.dll wasm test-browser --app=. --output-directory=/root/helix/work/workitem/uploads/xharness-output  --web-server-use-cors --web-server-use-https --set-web-server-http-env=DOTNET_TEST_WEBSOCKETHOST,DOTNET_TEST_HTTPHOST,DOTNET_TEST_REMOTE_LOOP_HOST --set-web-server-https-env=DOTNET_TEST_SECUREWEBSOCKETHOST,DOTNET_TEST_SECUREHTTPHOST,DOTNET_TEST_HTTP2HOST --web-server-middleware=/root/helix/work/correlation/xharness/RemoteLoopMiddleware/RemoteLoopServer.dll,RemoteLoopServer.GenericHandler --web-server-middleware=/root/helix/work/correlation/xharness/TestEchoMiddleware/NetCoreServer.dll,NetCoreServer.GenericHandler --web-server-use-cop -s dotnet.native.js.symbols --symbol-patterns wasm-symbol-patterns.txt --symbolicator WasmSymbolicator.dll,Microsoft.WebAssembly.Internal.SymbolicatorWrapperForXHarness --timeout=01:15:00     -- --setenv=XHARNESS_LOG_TEST_START=true --no-memory-snapshot --no-memory-snapshot --setenv=IsBrowserThreadingSupported=true  --run WasmTestRunner.dll System.Net.WebSockets.Client.Tests.dll  -backgroundExec -threads  -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing 
popd
===========================================================================================================
/root/helix/work/workitem/e /root/helix/work/workitem/e /root/helix/work/workitem/e
....
[09:08:42] info: 	[STRT] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_PassMultipleSubProtocols_ServerRequires_ConnectionUsesAgreedSubProtocol(server: ws://127.0.0.1:36481/WebSocket/EchoWebSocket.ashx)
[09:08:42] info: 	[PASS] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_PassMultipleSubProtocols_ServerRequires_ConnectionUsesAgreedSubProtocol
[09:08:42] info: 	[STRT] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_PassMultipleSubProtocols_ServerRequires_ConnectionUsesAgreedSubProtocol(server: wss://127.0.0.1:43369/WebSocket/EchoWebSocket.ashx)
[09:08:42] info: 	[PASS] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_PassMultipleSubProtocols_ServerRequires_ConnectionUsesAgreedSubProtocol
[09:08:42] info: 	[STRT] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_CancellationRequestedInflightConnect_ThrowsOperationCanceledException
[09:08:42] info: 	[PASS] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_CancellationRequestedInflightConnect_ThrowsOperationCanceledException
[09:08:42] info: 	[STRT] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_CancellationRequestedBeforeConnect_ThrowsOperationCanceledException
[09:08:42] info: 	[PASS] System.Net.WebSockets.Client.Tests.InvokerConnectTest.ConnectAsync_CancellationRequestedBeforeConnect_ThrowsOperationCanceledException
....
[09:08:42] fail: [0x000dc21c 09:08:42.595] MONO_WASM: {"status":1,"silent":true}
....
[09:08:42] fail: Application has finished with exit code TESTS_FAILED but 0 was expected
XHarness exit code: 71 (GENERAL_FAILURE)
/root/helix/work/workitem/e /root/helix/work/workitem/e
----- end Tue Jan 30 09:08:42 AM UTC 2024 ----- exit code 71 ----------------------------------------------------------

with coreclr test log from the same PR -- all the tests are passing, so no intermediate log is present:

pushd .
/datadisks/disk1/work/AE0F096E/p/dotnet exec --runtimeconfig System.Net.WebSockets.Client.Tests.runtimeconfig.json --depsfile System.Net.WebSockets.Client.Tests.deps.json xunit.console.dll System.Net.WebSockets.Client.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing 
popd
===========================================================================================================
/datadisks/disk1/work/AE0F096E/w/AC86092B/e /datadisks/disk1/work/AE0F096E/w/AC86092B/e
  Discovering: System.Net.WebSockets.Client.Tests (method display = ClassAndMethod, method display options = None)
  Discovered:  System.Net.WebSockets.Client.Tests (found 73 of 247 test cases)
  Starting:    System.Net.WebSockets.Client.Tests (parallel test collections = on [2 threads], stop on fail = off)
  Finished:    System.Net.WebSockets.Client.Tests
=== TEST EXECUTION SUMMARY ===
   System.Net.WebSockets.Client.Tests  Total: 108, Errors: 0, Failed: 0, Skipped: 0, Time: 3.548s
/datadisks/disk1/work/AE0F096E/w/AC86092B/e
----- end Tue Jan 30 09:22:54 AM UTC 2024 ----- exit code 0 ----------------------------------------------------------

I wonder if it is possible to set up CI not to write [info] messages instead of removing the ITestOutputHelper logs... 🤔

pavelsavara · 2024-01-30T12:32:15Z

I wonder if it is possible to set up CI not to write [info] messages instead of removing the ITestOutputHelper logs... 🤔

Yes, we have that XHARNESS_LOG_TEST_START=true which does the [STRT] part.
We turn in on with purpose for WebSocket tests right now, because we are debugging multi-threaded deadlocks on it.

The [PASS] we have for long time, I don't know how, but it's OK.

I don't insist we merge this. I just noticed that those output.WriteLine arrived with some recent merge and I thought they are a mistake. Maybe we didn't have any before in WS ?

@maraf do you know why our xharness/xunit produces output for non-failed tests? Where CoreCLR doesn't ?

It would be good to know how to turn this on/off.

CarnaViire · 2024-01-30T12:53:23Z

I just noticed that those output.WriteLine arrived with some recent merge and I thought they are a mistake. Maybe we didn't have any before in WS ?

These logs were there for a very long time. I assume, it was some recent WASM test runner change that started grabbing this output recently?

It would be good to know how to turn this on/off.

I agree 👍

ghost · 2024-01-30T13:01:00Z

Tagging subscribers to 'arch-wasm': @lewing
See info in area-owners.md if you want to be subscribed.

Issue Details

null

Author:	pavelsavara
Assignees:	pavelsavara
Labels:	`NO-MERGE`, `arch-wasm`, `area-System.Net.Http`, `os-browser`
Milestone:	9.0.0

reduce unit test noise in log files

b2b1263

pavelsavara added the area-System.Net.Http label Jan 29, 2024

pavelsavara added this to the 9.0.0 milestone Jan 29, 2024

pavelsavara requested review from CarnaViire and maraf January 29, 2024 16:52

pavelsavara self-assigned this Jan 29, 2024

pavelsavara marked this pull request as ready for review January 29, 2024 18:25

stephentoub reviewed Jan 30, 2024

View reviewed changes

pavelsavara closed this Jan 30, 2024

pavelsavara reopened this Jan 30, 2024

pavelsavara added NO-MERGE The PR is not ready for merge yet (see discussion for detailed reasons) os-browser Browser variant of arch-wasm arch-wasm WebAssembly architecture labels Jan 30, 2024

pavelsavara changed the title ~~reduce System.Net.WebSockets.Client.Tests noise in log files~~ [browser] reduce System.Net.WebSockets.Client.Tests noise in log files Jan 30, 2024

build-analysis bot mentioned this pull request Jan 30, 2024

Failed USB connection via port 54050, error 61, in tvOS arm64 Release AllSubsets_Mono #82637

Open

pavelsavara closed this Jan 30, 2024

github-actions bot locked and limited conversation to collaborators Mar 1, 2024

pavelsavara deleted the ws_tests_noise branch September 2, 2024 15:35

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[browser] reduce System.Net.WebSockets.Client.Tests noise in log files #97654

[browser] reduce System.Net.WebSockets.Client.Tests noise in log files #97654

pavelsavara commented Jan 29, 2024

ghost commented Jan 29, 2024

MihaZupan commented Jan 29, 2024

stephentoub Jan 30, 2024

pavelsavara commented Jan 30, 2024

pavelsavara commented Jan 30, 2024 •

edited

Loading

CarnaViire commented Jan 30, 2024

pavelsavara commented Jan 30, 2024

CarnaViire commented Jan 30, 2024 •

edited

Loading

ghost commented Jan 30, 2024

[browser] reduce System.Net.WebSockets.Client.Tests noise in log files #97654

[browser] reduce System.Net.WebSockets.Client.Tests noise in log files #97654

Conversation

pavelsavara commented Jan 29, 2024

ghost commented Jan 29, 2024

MihaZupan commented Jan 29, 2024

stephentoub Jan 30, 2024

Choose a reason for hiding this comment

pavelsavara commented Jan 30, 2024

pavelsavara commented Jan 30, 2024 • edited Loading

CarnaViire commented Jan 30, 2024

pavelsavara commented Jan 30, 2024

CarnaViire commented Jan 30, 2024 • edited Loading

ghost commented Jan 30, 2024

pavelsavara commented Jan 30, 2024 •

edited

Loading

CarnaViire commented Jan 30, 2024 •

edited

Loading