Improve wasm test logging #315

akoeplinger · 2020-09-28T15:57:26Z

Don't show PASS/SKIP messages by default in the console log, unless verbose logging is enabled in xharness.
We capture all output and store it in the wasm-console.log file in the xharness output directory instead.

I got many requests from various dotnet team members to make the default wasm output more similar to the desktop xunit output, which only displays failed tests by default.

The wasm output now looks like this:

  info: test[0] Discovering: System.Runtime.Handles.Tests.dll (method display = ClassAndMethod, method display options = None)
  info: test[0] Discovered:  System.Runtime.Handles.Tests.dll (found 14 of 15 test cases)
  info: test[0] Starting:    System.Runtime.Handles.Tests.dll
  fail: test[0] [FAIL] SafeWaitHandleTests.SafeWaitHandle_False
  info: test[0] Assert.False() Failure
  info: test[0] Expected: False
  info: test[0] Actual:   True
  info: test[0]    at SafeWaitHandleTests.SafeWaitHandle_False()
  info: test[0]    at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
  info: test[0] Finished:    System.Runtime.Handles.Tests.dll
  info: test[0]
  info: test[0] === TEST EXECUTION SUMMARY ===
  info: test[0] Total: 14, Errors: 0, Failed: 1, Skipped: 0, Time: 0.250726s

Don't show PASS/SKIP messages by default in the console log, unless verbose logging is enabled in xharness. We capture all output and store it in the wasm-console.log file in the xharness output directory instead. Also add special handling for FAIL messages so that they show up as a single entry in the console log output.

akoeplinger · 2020-09-28T15:59:18Z

src/Microsoft.DotNet.XHarness.TestRunners.Xunit/ThreadlessXunitTestRunner.cs

            var resultsXmlAssembly = new XElement("assembly");
            var resultsSink = new DelegatingXmlCreationSink(summarySink, resultsXmlAssembly);

+            if (Environment.GetEnvironmentVariable("XHARNESS_LOG_TEST_START") != null)


this is a useful unrelated feature for diagnosing hangs in tests :)

@akoeplinger could we update the README and add this?

CoffeeFlux · 2020-09-28T18:21:42Z

src/Microsoft.DotNet.XHarness.CLI/Commands/WASM/Browser/WasmBrowserTestRunner.cs

                    if (result.EndOfMessage)
                    {
                        var line = Encoding.UTF8.GetString(mem.GetBuffer(), 0, (int)mem.Length);
+                        line += Environment.NewLine;


Is this re-adding the newlines in between logger output messages? I really don't think we want this. It means every mono log entry will have them, which blows up quite quickly.

This only applies to the browser runner, it turned out that with #314 the non-browser (v8) runner would insert blank newlines after each line in the XML so I had to essentially revert it.

With this PR we'll only have the failed tests output in the console by default, the normal stdout goes to wasm-console.log which has no blank lines.

The mono logs not getting the newlines is good to hear, though I still don't follow why the non-browser runner is important here. Your sample output above seems like it has more newlines than I'd prefer. Desktop runner output:

~/git/runtime/artifacts/bin/System.Reflection.Tests/net5.0-release ~/git/runtime/src/libraries/System.Reflection/tests Discovering: System.Reflection.Tests (method display = ClassAndMethod, method display options = None) Discovered: System.Reflection.Tests (found 393 of 410 test cases) Starting: System.Reflection.Tests (parallel test collections = on, max threads = 12) System.Reflection.Tests.TypeInfoTests.Namespace(type: typeof(System.Reflection.Tests.TI_BaseClass+PublicNestedClass1[]), expected: "System.Reflection.Tests") [FAIL] Assert.Equal() Failure Expected: System.Reflection.Tests Actual: (null) Stack Trace: /Users/ryan/git/runtime/src/libraries/System.Reflection/tests/TypeInfoTests.cs(1414,0): at System.Reflection.Tests.TypeInfoTests.Namespace(Type type, String expected) /Users/ryan/git/runtime/src/mono/netcore/System.Private.CoreLib/src/System/Reflection/RuntimeMethodInfo.cs(384,0): at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) Finished: System.Reflection.Tests === TEST EXECUTION SUMMARY === System.Reflection.Tests Total: 1283, Errors: 0, Failed: 1, Skipped: 0, Time: 0.941s ~/git/runtime/src/libraries/System.Reflection/tests

The issue is basically #314 (comment)

I'll make it a bit more similar to the desktop runner output.

Turns out the newest version of the Microsoft.Extensions.Logging package made improvements in that area and we can now get much closer to what we want (still no easy way to strip out the test[0] though).

It now looks like this:

info: test[0] Discovering: System.Runtime.Handles.Tests.dll (method display = ClassAndMethod, method display options = None) info: test[0] Discovered: System.Runtime.Handles.Tests.dll (found 14 of 15 test cases) info: test[0] Starting: System.Runtime.Handles.Tests.dll fail: test[0] [FAIL] SafeWaitHandleTests.SafeWaitHandle_False info: test[0] Assert.False() Failure info: test[0] Expected: False info: test[0] Actual: True info: test[0] at SafeWaitHandleTests.SafeWaitHandle_False() info: test[0] at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) info: test[0] Finished: System.Runtime.Handles.Tests.dll info: test[0] info: test[0] === TEST EXECUTION SUMMARY === info: test[0] Total: 14, Errors: 0, Failed: 1, Skipped: 0, Time: 0.250726s

…line logging

akoeplinger · 2020-09-29T00:48:19Z

/azp run

azure-pipelines · 2020-09-29T00:48:28Z

Azure Pipelines successfully started running 1 pipeline(s).

…nuget We were pulling in Microsoft.AspNetCore 2.2 via a nuget PackageReference, but after upgrading Microsoft.Extensions.Logging in dotnet#315 we saw the following error when using the "wasm test-browser" command: ``` �[41m�[30mfail�[39m�[22m�[49m: Microsoft.AspNetCore.Server.Kestrel[0] Heartbeat.OnHeartbeat System.TypeLoadException: Could not load type 'Microsoft.Extensions.Primitives.InplaceStringBuilder' from assembly 'Microsoft.Extensions.Primitives, Version=5.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60'. at Microsoft.Net.Http.Headers.DateTimeFormatter.ToRfc1123String(DateTimeOffset dateTime, Boolean quoted) at Microsoft.Net.Http.Headers.HeaderUtilities.FormatDate(DateTimeOffset dateTime, Boolean quoted) at Microsoft.Net.Http.Headers.HeaderUtilities.FormatDate(DateTimeOffset dateTime) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.DateHeaderValueManager.SetDateValues(DateTimeOffset value) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.DateHeaderValueManager.OnHeartbeat(DateTimeOffset now) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.Heartbeat.OnHeartbeat() ``` The reason is that the newer version of Microsoft.Extensions.Primitives removed InplaceStringBuilder. Instead of using an old ASP.NET we can use the one in the framework instead, which is what's recommended since .NET Core 3.0

…nuget (#324) * Use latest version of ASP.NET Core via FrameworkReference instead of nuget We were pulling in Microsoft.AspNetCore 2.2 via a nuget PackageReference, but after upgrading Microsoft.Extensions.Logging in #315 we saw the following error when using the "wasm test-browser" command: ``` �[41m�[30mfail�[39m�[22m�[49m: Microsoft.AspNetCore.Server.Kestrel[0] Heartbeat.OnHeartbeat System.TypeLoadException: Could not load type 'Microsoft.Extensions.Primitives.InplaceStringBuilder' from assembly 'Microsoft.Extensions.Primitives, Version=5.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60'. at Microsoft.Net.Http.Headers.DateTimeFormatter.ToRfc1123String(DateTimeOffset dateTime, Boolean quoted) at Microsoft.Net.Http.Headers.HeaderUtilities.FormatDate(DateTimeOffset dateTime, Boolean quoted) at Microsoft.Net.Http.Headers.HeaderUtilities.FormatDate(DateTimeOffset dateTime) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.DateHeaderValueManager.SetDateValues(DateTimeOffset value) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.DateHeaderValueManager.OnHeartbeat(DateTimeOffset now) at Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.Heartbeat.OnHeartbeat() ``` The reason is that the newer version of Microsoft.Extensions.Primitives removed InplaceStringBuilder. Instead of using an old ASP.NET we can use the one in the framework instead, which is what's recommended since .NET Core 3.0 * Update helix SDK to fix tests

With dotnet/xharness#315 we can now make the test output similar to the regular xunit desktop runner. It no longer prints the passed tests by default, only failing tests. To get the old behavior, add the `-v` flag back to xharness in tests.mobile.targets or check the new wasm-console.log file in the xharness-output folder. ``` XHarness command issued: wasm test --app=. --engine=V8 --engine-arg=--stack-trace-limit=1000 --js-file=runtime.js --output-directory=/Users/alexander/dev/runtime/artifacts/bin/System.Runtime.Handles.Tests/net5.0-Release/browser-wasm/AppBundle/xharness-output -- --run WasmTestRunner.dll System.Runtime.Handles.Tests.dll -notrait category=OuterLoop -notrait category=failing info: 21:57:45.3244690 v8 --expose_wasm --stack-trace-limit=1000 runtime.js -- --run WasmTestRunner.dll System.Runtime.Handles.Tests.dll -notrait category=OuterLoop -notrait category=failing info: Arguments: --run,WasmTestRunner.dll,System.Runtime.Handles.Tests.dll,-notrait,category=OuterLoop,-notrait,category=failing info: console.debug: MONO_WASM: Initializing mono runtime info: console.debug: MONO_WASM: ICU data archive(s) loaded, disabling invariant mode info: console.debug: mono_wasm_runtime_ready fe00e07a-5519-4dfe-b35a-f867dbaf2e28 info: Initializing..... info: Discovering: System.Runtime.Handles.Tests.dll (method display = ClassAndMethod, method display options = None) info: Discovered: System.Runtime.Handles.Tests.dll (found 14 of 15 test cases) info: Starting: System.Runtime.Handles.Tests.dll fail: [FAIL] SafeWaitHandleTests.SafeWaitHandle_False info: Assert.False() Failure info: Expected: False info: Actual: True info: at SafeWaitHandleTests.SafeWaitHandle_False() info: at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) info: Finished: System.Runtime.Handles.Tests.dll info: info: === TEST EXECUTION SUMMARY === info: Total: 14, Errors: 0, Failed: 1, Skipped: 0, Time: 0.097211s info: info: 21:57:46.3323620 Process exited with 1 ```

akoeplinger requested review from CoffeeFlux, lewing and radical September 28, 2020 15:57

akoeplinger commented Sep 28, 2020

View reviewed changes

CoffeeFlux reviewed Sep 28, 2020

View reviewed changes

Update to new Microsoft.Extensions.Logging version and enable single-…

9f0b836

…line logging

CoffeeFlux approved these changes Sep 29, 2020

View reviewed changes

radical approved these changes Sep 29, 2020

View reviewed changes

lewing approved these changes Sep 29, 2020

View reviewed changes

akoeplinger merged commit f4af4bc into dotnet:master Sep 29, 2020

akoeplinger deleted the improve-wasm-logging branch September 29, 2020 01:32

akoeplinger mentioned this pull request Sep 29, 2020

Update README with XHARNESS_LOG_TEST_START env var #316

Merged

akoeplinger mentioned this pull request Sep 29, 2020

Improve WASM test output via xharness dotnet/runtime#42860

Merged

akoeplinger mentioned this pull request Oct 2, 2020

Use latest version of ASP.NET Core via FrameworkReference instead of nuget #324

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Improve wasm test logging #315

Improve wasm test logging #315

Uh oh!

akoeplinger commented Sep 28, 2020 •

edited

Loading

Uh oh!

akoeplinger Sep 28, 2020

Uh oh!

premun Sep 29, 2020

Uh oh!

CoffeeFlux Sep 28, 2020

Uh oh!

akoeplinger Sep 28, 2020 •

edited

Loading

Uh oh!

CoffeeFlux Sep 28, 2020

Uh oh!

akoeplinger Sep 28, 2020

Uh oh!

akoeplinger Sep 28, 2020

Uh oh!

akoeplinger commented Sep 29, 2020

Uh oh!

azure-pipelines bot commented Sep 29, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

Improve wasm test logging #315

Improve wasm test logging #315

Uh oh!

Conversation

akoeplinger commented Sep 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

akoeplinger Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

premun Sep 29, 2020

Choose a reason for hiding this comment

Uh oh!

CoffeeFlux Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

akoeplinger Sep 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

CoffeeFlux Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

akoeplinger Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

akoeplinger Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

akoeplinger commented Sep 29, 2020

Uh oh!

azure-pipelines bot commented Sep 29, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

akoeplinger commented Sep 28, 2020 •

edited

Loading

akoeplinger Sep 28, 2020 •

edited

Loading