[wasm] Malformed `testResults.xml` causing CI test runs to fail #61749

radical · 2021-11-17T20:52:01Z

Tests pass:

[18:29:38] info: Total: 1485, Errors: 0, Failed: 0, Skipped: 0, Time: 5.652435s
[18:29:38] info: 
[18:29:38] info: Flushed stdout!
[18:29:38] info: 1 Exit called with 0 when isXUnitDoneCheck=true  at set_exit_code (/main.js:240:24) at Object.init (/main.js:204:17).
[18:29:38] info: WASM EXIT 0

but then the log parsing fails:

Traceback (most recent call last):
  File "/datadisks/disk1/work/99FB08BE/p/reporter/run.py", line 68, in <module>
    main()
  File "/datadisks/disk1/work/99FB08BE/p/reporter/run.py", line 65, in main
    reporter.report_results(all_results)
  File "/etc/helix/scripts/helix/test_reporting/packing_test_reporter.py", line 27, in report_results
    results = [x for x in results if x]
  File "/etc/helix/scripts/helix/test_reporting/packing_test_reporter.py", line 27, in <listcomp>
    results = [x for x in results if x]
  File "/datadisks/disk1/work/99FB08BE/p/reporter/test_results_reader/__init__.py", line 99, in read_results
    for result in file_results:
  File "/datadisks/disk1/work/99FB08BE/p/reporter/test_results_reader/__init__.py", line 98, in <genexpr>
    file_results = (add_logs(tr, log_list) for tr in f.read_results(file_path))
  File "/datadisks/disk1/work/99FB08BE/p/reporter/formats/xunit.py", line 47, in read_results
    for (_, element) in xml.etree.ElementTree.iterparse(path, events=['end']):
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1221, in iterator
    yield from pullparser.read_events()
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1296, in read_events
    raise event
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1268, in feed
    self._parser.feed(data)
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1101, column 6

Lines 1100,1101 from testResults.xml:

      <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest181" type="XPathTests.FunctionalTests.Expressions.NodeSetsTests" method="NodeSetsTest181" time="0.000645" result="Pass" />  <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest183" type="XPathTests.FunctionalTests.E
      <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest185" type="XPathTests.FunctionalTests.Expressions.NodeSetsTests" method="NodeSetsTest185" time="0.00062" result="Pass" />

The top line there (1100) has an incomplete element:
<test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest183" type="XPathTests.FunctionalTests.E at the end.

cc @pavelsavara

The text was updated successfully, but these errors were encountered:

ghost · 2021-11-17T20:52:04Z

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

Issue Details

Seen on #59479, build, log

Tests pass:

[18:29:38] info: Total: 1485, Errors: 0, Failed: 0, Skipped: 0, Time: 5.652435s
[18:29:38] info: 
[18:29:38] info: Flushed stdout!
[18:29:38] info: 1 Exit called with 0 when isXUnitDoneCheck=true  at set_exit_code (/main.js:240:24) at Object.init (/main.js:204:17).
[18:29:38] info: WASM EXIT 0

but then the log parsing fails:

Traceback (most recent call last):
  File "/datadisks/disk1/work/99FB08BE/p/reporter/run.py", line 68, in <module>
    main()
  File "/datadisks/disk1/work/99FB08BE/p/reporter/run.py", line 65, in main
    reporter.report_results(all_results)
  File "/etc/helix/scripts/helix/test_reporting/packing_test_reporter.py", line 27, in report_results
    results = [x for x in results if x]
  File "/etc/helix/scripts/helix/test_reporting/packing_test_reporter.py", line 27, in <listcomp>
    results = [x for x in results if x]
  File "/datadisks/disk1/work/99FB08BE/p/reporter/test_results_reader/__init__.py", line 99, in read_results
    for result in file_results:
  File "/datadisks/disk1/work/99FB08BE/p/reporter/test_results_reader/__init__.py", line 98, in <genexpr>
    file_results = (add_logs(tr, log_list) for tr in f.read_results(file_path))
  File "/datadisks/disk1/work/99FB08BE/p/reporter/formats/xunit.py", line 47, in read_results
    for (_, element) in xml.etree.ElementTree.iterparse(path, events=['end']):
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1221, in iterator
    yield from pullparser.read_events()
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1296, in read_events
    raise event
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1268, in feed
    self._parser.feed(data)
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1101, column 6

Lines 1100,1101 from testResults.xml:

      <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest181" type="XPathTests.FunctionalTests.Expressions.NodeSetsTests" method="NodeSetsTest181" time="0.000645" result="Pass" />  <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest183" type="XPathTests.FunctionalTests.E
      <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest185" type="XPathTests.FunctionalTests.Expressions.NodeSetsTests" method="NodeSetsTest185" time="0.00062" result="Pass" />

The top line there (1100) has an incomplete element:
<test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest183" type="XPathTests.FunctionalTests.E at the end.

cc @pavelsavara

Author:	radical
Assignees:	-
Labels:	`arch-wasm`
Milestone:	-

dotnet-issue-labeler · 2021-11-17T20:52:05Z

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

pavelsavara · 2021-11-17T21:25:25Z

@radical
Are you saying that the xml is damaged in the middle of line ? If so, that's very interesting.

radical · 2021-11-17T21:29:30Z

Yep, you can see the xml here - https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-59479-merge-305953aa61524883b7/System.Xml.XPath.XmlDocument.Tests/1/xharness-output/testResults.xml?sv=2019-07-07&

pavelsavara · 2021-11-17T21:34:46Z

See how emscripten implaments putChar on stdout.
Could it be that something writes to it in between our resultsXml.Save ?

pavelsavara · 2021-11-17T21:35:29Z

I mean into the tty.output char buffer there.

pavelsavara · 2021-11-17T21:47:13Z

Or it could be buffering of WasmBrowserTestRunner
Or it could be browser console buffers or webSocket buffers on both sides.

pavelsavara · 2021-11-18T12:11:17Z

Possibly related ? xunit/xunit#2090

pavelsavara · 2021-11-18T14:05:31Z

We noticed that WasmConsoleStream.Flush is probably NOOP.

runtime/src/libraries/System.Console/src/System/ConsolePal.WebAssembly.cs

Line 71 in f1bf5ee

base.Flush();

See base ConsoleStream

runtime/src/libraries/System.Console/src/System/IO/ConsoleStream.cs

Line 65 in 57bfe47

public override void Flush()

pavelsavara · 2021-11-18T15:06:14Z

We noticed that WasmConsoleStream.Flush is probably NOOP.

That's the case for all platforms. So there is no point in calling it.

ghost · 2021-11-18T15:26:08Z

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

Issue Details

Seen on #59479, build, log

Tests pass:

[18:29:38] info: Total: 1485, Errors: 0, Failed: 0, Skipped: 0, Time: 5.652435s
[18:29:38] info: 
[18:29:38] info: Flushed stdout!
[18:29:38] info: 1 Exit called with 0 when isXUnitDoneCheck=true  at set_exit_code (/main.js:240:24) at Object.init (/main.js:204:17).
[18:29:38] info: WASM EXIT 0

but then the log parsing fails:

Traceback (most recent call last):
  File "/datadisks/disk1/work/99FB08BE/p/reporter/run.py", line 68, in <module>
    main()
  File "/datadisks/disk1/work/99FB08BE/p/reporter/run.py", line 65, in main
    reporter.report_results(all_results)
  File "/etc/helix/scripts/helix/test_reporting/packing_test_reporter.py", line 27, in report_results
    results = [x for x in results if x]
  File "/etc/helix/scripts/helix/test_reporting/packing_test_reporter.py", line 27, in <listcomp>
    results = [x for x in results if x]
  File "/datadisks/disk1/work/99FB08BE/p/reporter/test_results_reader/__init__.py", line 99, in read_results
    for result in file_results:
  File "/datadisks/disk1/work/99FB08BE/p/reporter/test_results_reader/__init__.py", line 98, in <genexpr>
    file_results = (add_logs(tr, log_list) for tr in f.read_results(file_path))
  File "/datadisks/disk1/work/99FB08BE/p/reporter/formats/xunit.py", line 47, in read_results
    for (_, element) in xml.etree.ElementTree.iterparse(path, events=['end']):
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1221, in iterator
    yield from pullparser.read_events()
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1296, in read_events
    raise event
  File "/usr/lib/python3.6/xml/etree/ElementTree.py", line 1268, in feed
    self._parser.feed(data)
xml.etree.ElementTree.ParseError: not well-formed (invalid token): line 1101, column 6

Lines 1100,1101 from testResults.xml:

      <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest181" type="XPathTests.FunctionalTests.Expressions.NodeSetsTests" method="NodeSetsTest181" time="0.000645" result="Pass" />  <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest183" type="XPathTests.FunctionalTests.E
      <test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest185" type="XPathTests.FunctionalTests.Expressions.NodeSetsTests" method="NodeSetsTest185" time="0.00062" result="Pass" />

The top line there (1100) has an incomplete element:
<test name="XPathTests.FunctionalTests.Expressions.NodeSetsTests.NodeSetsTest183" type="XPathTests.FunctionalTests.E at the end.

cc @pavelsavara

Author:	radical
Assignees:	-
Labels:	`arch-wasm`, `blocking-clean-ci`, `area-Infrastructure-mono`
Milestone:	7.0.0

eerhardt · 2021-11-19T00:22:18Z

Happened again in #57433.

https://helix.dot.net/api/2019-06-17/jobs/8af8ecaf-88ce-43d9-b770-3dc95fe1fddc/workitems/System.Xml.Linq.Events.Tests/console

radical · 2021-11-19T22:02:49Z

Another one, but failing because:

2 Exit called with 0 when isXUnitDoneCheck=true  at set_exit_code (/main.js:240:24) at Object.init (/main.js:204:17).
<?xml version="1.0" encoding="utf-8"?>
<assemblies>

.. that debug message is showing up in the xml.

And another with:

<?xml version="1.0" encoding="utf-8"?>
2 Exit called with 0 when isXUnitDoneCheck=true  at set_exit_code (/main.js:240:24) at Object.init (/main.js:204:17).
<assemblies>

.. again with the debug message showing up in the second line.

Build

pavelsavara · 2021-11-20T21:06:01Z

Both messages thru WS and thru chrome devtools protocol are written into same WasmTestMessagesProcessor.
Those sources are running in parallel.

radical added the arch-wasm WebAssembly architecture label Nov 17, 2021

dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Nov 17, 2021

radical added the blocking-clean-ci Blocking PR or rolling runs of 'runtime' or 'runtime-extra-platforms' label Nov 17, 2021

runfoapp bot mentioned this issue Nov 17, 2021

Infrastructure - Status/Health #702

Closed

radical mentioned this issue Nov 17, 2021

[wasm] Run AOT, and Wasm.Build.Tests on windows #59479

Merged

lewing removed the untriaged New issue has not been triaged by the area owner label Nov 17, 2021

lewing added this to the 7.0.0 milestone Nov 17, 2021

jeffschwMSFT added the area-Infrastructure-mono label Nov 18, 2021

eerhardt mentioned this issue Nov 19, 2021

[Group 4] Enable nullable annotations for Microsoft.Extensions.Configuration.EnvironmentVariables #57433

Merged

pavelsavara mentioned this issue Nov 19, 2021

[wasm] workaround test results corruption #61841

Merged

pavelsavara mentioned this issue Nov 20, 2021

[wasm] write test as single line via base64 dotnet/xharness#771

Merged

pavelsavara self-assigned this Nov 20, 2021

ghost added the in-pr There is an active PR which will close this issue when it is merged label Nov 23, 2021

pavelsavara closed this as completed in #61841 Nov 23, 2021

ghost removed the in-pr There is an active PR which will close this issue when it is merged label Nov 23, 2021

ghost locked as resolved and limited conversation to collaborators Dec 23, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[wasm] Malformed `testResults.xml` causing CI test runs to fail #61749

[wasm] Malformed `testResults.xml` causing CI test runs to fail #61749

radical commented Nov 17, 2021

ghost commented Nov 17, 2021

dotnet-issue-labeler bot commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

radical commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

pavelsavara commented Nov 18, 2021

pavelsavara commented Nov 18, 2021

pavelsavara commented Nov 18, 2021

ghost commented Nov 18, 2021

eerhardt commented Nov 19, 2021

radical commented Nov 19, 2021

pavelsavara commented Nov 20, 2021

[wasm] Malformed testResults.xml causing CI test runs to fail #61749

[wasm] Malformed testResults.xml causing CI test runs to fail #61749

Comments

radical commented Nov 17, 2021

ghost commented Nov 17, 2021

dotnet-issue-labeler bot commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

radical commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

pavelsavara commented Nov 17, 2021

pavelsavara commented Nov 18, 2021

pavelsavara commented Nov 18, 2021

pavelsavara commented Nov 18, 2021

ghost commented Nov 18, 2021

eerhardt commented Nov 19, 2021

radical commented Nov 19, 2021

pavelsavara commented Nov 20, 2021

[wasm] Malformed `testResults.xml` causing CI test runs to fail #61749

[wasm] Malformed `testResults.xml` causing CI test runs to fail #61749