search

dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.34k stars 4.74k forks source link

XUnit log fixer creates invalid XML when fixing the xml after a timed out test #84940

Closed trylek closed 1 year ago

trylek commented 1 year ago

Platform: Windows arm checked Example run: https://dev.azure.com/dnceng-public/public/_build/results?buildId=241282&view=ms.vss-test-web.build-test-results-tab&runId=4637564&resultId=122180&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab Failing test: Directed_1

Diagnostics:

...
END EXECUTION - PASSED
PASSED
Test Harness Exitcode is : 0
To run the test:
Set up CORE_ROOT and run.
> C:\h\w\A9F7091C\w\9FAC08C6\e\JIT\Directed\Directed_1\../callconv/ThisCall/EmptyThisCallTest/EmptyThisCallTest.cmd
10:48:09.033 Passed test: JIT/Directed/callconv/ThisCall/EmptyThisCallTest/EmptyThisCallTest.cmd
10:48:09.036 Running test: JIT/Directed/debugging/debuginfo/tester/tester.cmd

cmdLine:C:\h\w\A9F7091C\w\9FAC08C6\e\JIT\Directed\Directed_1\../debugging/debuginfo/tester/tester.cmd Timed Out (timeout in milliseconds: 1800000 from variable __TestTimeout, start: 4/17/2023 10:48:09 AM, end: 4/17/2023 11:18:09 AM)

Return code:      -100
Raw output file:      C:\h\w\A9F7091C\w\9FAC08C6\uploads\debugging\debuginfo\tester\output.txt
Raw output:

cmdLine:C:\h\w\A9F7091C\w\9FAC08C6\e\JIT\Directed\Directed_1\../debugging/debuginfo/tester/tester.cmd Timed Out (timeout in milliseconds: 1800000 from variable __TestTimeout, start: 4/17/2023 10:48:09 AM, end: 4/17/2023 11:18:09 AM)
Test Harness Exitcode is : -100
To run the test:
Set up CORE_ROOT and run.
> C:\h\w\A9F7091C\w\9FAC08C6\e\JIT\Directed\Directed_1\../debugging/debuginfo/tester/tester.cmd
11:18:09.123 Failed test: JIT/Directed/debugging/debuginfo/tester/tester.cmd
11:18:09.123 Running test: JIT/Directed/forceinlining/AttributeConflict/AttributeConflict.cmd
11:18:09.207 Failed test: JIT/Directed/forceinlining/AttributeConflict/AttributeConflict.cmd
11:18:09.208 Running test: JIT/Directed/forceinlining/PositiveCases/PositiveCases.cmd
11:18:09.274 Failed test: JIT/Directed/forceinlining/PositiveCases/PositiveCases.cmd
11:18:09.275 Running test: JIT/Directed/IL/PInvokeTail/PInvokeTail/PInvokeTail.cmd
Unhandled exception. 
   Cannot print exception string because Exception.ToString() failed.
App Exit Code: -1073741819
Expected: 100
Actual: -1073741819
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'Directed_1' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

106/128 tests run.
* 93 tests passed.
* 4 tests failed.
* 9 tests skipped.

[XUnitLogChecker]: Checking for dumps...
Unhandled exception. System.Xml.XmlException: The 'assembly' start tag on line 1 position 2 does not match the end tag of 'stack'. Line 267, position 3.
   at System.Xml.XmlTextReaderImpl.Throw(Exception e)
   at System.Xml.XmlTextReaderImpl.Throw(String res, String[] args)
   at System.Xml.XmlTextReaderImpl.ThrowTagMismatch(NodeData startTag)
   at System.Xml.XmlTextReaderImpl.ParseEndElement()
   at System.Xml.XmlTextReaderImpl.ParseElementContent()
   at System.Xml.XmlTextReaderImpl.Read()
   at System.Xml.Linq.XContainer.ReadContentFrom(XmlReader r)
   at System.Xml.Linq.XContainer.ReadContentFrom(XmlReader r, LoadOptions o)
   at System.Xml.Linq.XElement.ReadElementFrom(XmlReader r, LoadOptions o)
   at System.Xml.Linq.XElement.Load(XmlReader reader, LoadOptions options)
   at System.Xml.Linq.XElement.Load(String uri, LoadOptions options)
   at XUnitLogChecker.PrintStackTracesFromDumps(String dumpsPath, String tempLogPath) in D:\a\_work\1\s\src\tests\Common\XUnitLogChecker\XUnitLogChecker.cs:line 396
   at XUnitLogChecker.Main(String[] args) in D:\a\_work\1\s\src\tests\Common\XUnitLogChecker\XUnitLogChecker.cs:line 153
ERROR: The process "corerun.exe" not found.
2023-04-17T11:18:40.639Z    INFO    run.py  run(48) main    Beginning reading of test results.
2023-04-17T11:18:40.639Z    INFO    run.py  __init__(42)    read_results    Searching 'C:\h\w\A9F7091C\w\9FAC08C6\e' for test results files
2023-04-17T11:18:40.670Z    INFO    run.py  __init__(42)    read_results    Searching 'C:\h\w\A9F7091C\w\9FAC08C6\uploads' for test results files
2023-04-17T11:18:40.670Z    WARNING run.py  __init__(55)    read_results    No results file found in any of the following formats: xunit, junit, trx
2023-04-17T11:18:40.670Z    INFO    run.py  packing_test_reporter(30)   report_results  Packing 0 test reports to 'C:\h\w\A9F7091C\w\9FAC08C6\e\__test_report.json'
2023-04-17T11:18:40.670Z    INFO    run.py  packing_test_reporter(33)   report_results  Packed 1539 bytes
['Directed_1' END OF WORK ITEM LOG: Command exited with -532462766]

/cc @ivdiazsa @jkoritzinsky @dotnet/runtime-infrastructure

trylek commented 1 year ago

Another instance after a test crash:

https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-216d87cd237644afba/threading_group2/1/console.3d9af0d4.log?helixlogtype=result

Pipeline: https://dev.azure.com/dnceng-public/public/_build/results?buildId=241126&view=ms.vss-test-web.build-test-results-tab&runId=4632920&resultId=122456&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab Platform: Windows arm checked (without R2R) Test: threading_group2

Diagnostics:

Unhandled exception. System.NullReferenceException: Object reference not set to an instance of an object.
   at MyData.ThreadTarget()
   at System.Threading.Thread.StartCallback()
App Exit Code: -1073741819
Expected: 100
Actual: -1073741819
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'threading_group2' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

77/95 tests run.
* 47 tests passed.
* 30 tests failed.
* 0 tests skipped.

[XUnitLogChecker]: Checking for dumps...
Unhandled exception. System.Xml.XmlException: The 'assembly' start tag on line 1 position 2 does not match the end tag of 'stack'. Line 219, position 3.
   at System.Xml.XmlTextReaderImpl.Throw(Exception e)
   at System.Xml.XmlTextReaderImpl.Throw(String res, String[] args)
   at System.Xml.XmlTextReaderImpl.ThrowTagMismatch(NodeData startTag)
   at System.Xml.XmlTextReaderImpl.ParseEndElement()
   at System.Xml.XmlTextReaderImpl.ParseElementContent()
   at System.Xml.XmlTextReaderImpl.Read()
   at System.Xml.Linq.XContainer.ReadContentFrom(XmlReader r)
   at System.Xml.Linq.XContainer.ReadContentFrom(XmlReader r, LoadOptions o)
   at System.Xml.Linq.XElement.ReadElementFrom(XmlReader r, LoadOptions o)
   at System.Xml.Linq.XElement.Load(XmlReader reader, LoadOptions options)
   at System.Xml.Linq.XElement.Load(String uri, LoadOptions options)
   at XUnitLogChecker.PrintStackTracesFromDumps(String dumpsPath, String tempLogPath) in D:\a\_work\1\s\src\tests\Common\XUnitLogChecker\XUnitLogChecker.cs:line 396
   at XUnitLogChecker.Main(String[] args) in D:\a\_work\1\s\src\tests\Common\XUnitLogChecker\XUnitLogChecker.cs:line 153
ivdiazsa commented 1 year ago

I finally got to hack up an artificial repro of this problem. It seems the log fixer is getting confused when dealing with stack-traces in logs, due to them being inside the output tags. I will take a look at that and come up with a fix soon.

ivdiazsa commented 1 year ago

Just as I developed a fix for this, I came across another bug that will blow up at some point. Could be tomorrow, could be in a month. So, I'm going to address that one too and therefore the PR will take a little bit longer.