Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Test failure error message is unreadable in Azure DevOps #1664

Open
BruceForstall opened this issue Jan 13, 2020 · 25 comments
Open

Test failure error message is unreadable in Azure DevOps #1664

BruceForstall opened this issue Jan 13, 2020 · 25 comments

Comments

@BruceForstall
Copy link
Member

When a test fails, and you view the Error Message in Azure DevOps, you get something like this:

\ncmdLine:/private/tmp/helix/working/B08009A5/w/A2FA08B1/e/Interop/ICustomMarshaler/Primitives/ICustomMarshaler/ICustomMarshaler.sh Timed Out\n\nReturn code: -100\nRaw output file: /private/tmp/helix/working/B08009A5/w/A2FA08B1/e/Interop/ICustomMarshaler/Reports/Interop.ICustomMarshaler/Primitives/ICustomMarshaler/ICustomMarshaler.output.txt\nRaw output:\nBEGIN EXECUTION\n/tmp/helix/working/B08009A5/p/corerun ICustomMarshaler.dll ''\nDiscovering...\n\ncmdLine:/private/tmp/helix/working/B08009A5/w/A2FA08B1/e/Interop/ICustomMarshaler/Primitives/ICustomMarshaler/ICustomMarshaler.sh Timed Out\nTest Harness Exitcode is : -100\nTo run the test:\n> set CORE_ROOT=/tmp/helix/working/B08009A5/p\n> /private/tmp/helix/working/B08009A5/w/A2FA08B1/e/Interop/ICustomMarshaler/Primitives/ICustomMarshaler/ICustomMarshaler.sh\nExpected: True\nActual: False

This is unreadable. We need proper line breaking in the view instead of the embedded \n characters.

@dotnet/runtime-infrastructure

@Dotnet-GitSync-Bot Dotnet-GitSync-Bot added the untriaged New issue has not been triaged by the area owner label Jan 13, 2020
@jaredpar
Copy link
Member

@BruceForstall can you link to a build / run that has this issue?

@ericstj
Copy link
Member

ericstj commented Jan 15, 2020

/cc @ViktorHofer

@BruceForstall
Copy link
Member Author

To make it worse, the AzDO UI for viewing ends up creating a very wide window with a horizontal scrollbar, so you have to constantly scroll back-and-forth (and read through a mass of no-whitespace text) to find the relevant bits of information.

@dagood
Copy link
Member

dagood commented Jan 27, 2020

I always copy the text out and replace escaped newlines with newlines in np++. I would love to see this fixed.

@jaredpar
Copy link
Member

It looks like the Linux/Mac jobs have \n but the Windows jobs have \r\n text:

I've complained to AzDO about this before (we have same issue in Roslyn). They constantly push back the issue is on our end not there's but even when digging in I could never see where we were doing extra escaping.

@jkoritzinsky
Copy link
Member

Is it possible that it's the Helix xunit reporter that's doing the escaping? That's the common factor between Roslyn and dotnet/runtime that other repos using xunit on AzDO don't have.

@BruceForstall
Copy link
Member Author

Is it possible that it's the Helix xunit reporter that's doing the escaping? That's the common factor between Roslyn and dotnet/runtime that other repos using xunit on AzDO don't have.

@MattGal Can you suggest someone with knowledge of the Helix xunit reporter upload to AzDO that might be able to investigate this?

@jaredpar
Copy link
Member

@jkoritzinsky

Is it possible that it's the Helix xunit reporter that's doing the escaping? That's the common factor between Roslyn and dotnet/runtime that other repos using xunit on AzDO don't have.

Roslyn doesn't use Helix yet so it's not a common factor for this.

Note: it should be possible to see if we are or aren't escaping by looking at the raw xUnit logs. They should be available in XML form for every test that fails in Helix correct? If so we can just look there and see if the values are escaped. That would at least eliminate infra in dotnet/runtime as the culprit.

@MattGal
Copy link
Member

MattGal commented Jan 28, 2020

Is it possible that it's the Helix xunit reporter that's doing the escaping? That's the common factor between Roslyn and dotnet/runtime that other repos using xunit on AzDO don't have.

@MattGal Can you suggest someone with knowledge of the Helix xunit reporter upload to AzDO that might be able to investigate this?

@jaredpar 's comment likely obviates this but you can read the full sources here: https://github.com/dotnet/arcade/blob/master/src/Microsoft.DotNet.Helix/Sdk/tools/azure-pipelines/reporter/azure_devops_result_publisher.py and @alexperovich wrote it.

@alexperovich
Copy link
Member

The build linked in the issue is too old for the results file to still exist. I looked at the latest build but the xunit file isn't avaliable for the JIT.HardwareIntrinsics work item. If we can catch another instance I can grab the xunit file and check.

@alexperovich
Copy link
Member

That workitem doesn't have the test results file uploaded for some reason. The older one did, it just doesn't exist anymore.

@BruceForstall
Copy link
Member Author

@alexperovich What should I look for to find the uploaded test results file?

Is there logging in this case that indicates why there is no uploaded test results file?

@alexperovich
Copy link
Member

I just used the JobId and WorkItemId in the Comments section in this api https://helix.dot.net/swagger/ui/index#!/WorkItem/WorkItem_ListFiles

I believe the xunit file is only avaliable in that old run because you guys have the legacy xunit reporter turned on. The VSTS reporter doesn't actually upload the file.

@BruceForstall
Copy link
Member Author

@alexperovich When I look at the Helix api above I can grab the console log for my example case, here:

https://helix.dot.net/api/2019-06-17/jobs/d6ddab18-811b-40b1-b694-f49decd8f192/workitems/JIT.HardwareIntrinsics/files/console.17dc63b4.log

This has some interesting sections, e.g. uploading the results:

+ /home/helixbot/.vsts-env/bin/python /root/helix/work/correlation/reporter/run.py https://dev.azure.com/dnceng/ public 15859996 eyJ0eXAiOiJKV1QiLCJhbGciOiJSUzI1NiIsIng1dCI6Im9PdmN6NU1fN3AtSGpJS2xGWHo5M3VfVjBabyJ9.eyJuYW1laWQiOiJlNDI4NWM4Yy0zZmQ1LTQyNjctOWIxYy00MjE5NWM0N2E1NTMiLCJzY3AiOiJhcHBfdG9rZW4iLCJhdWkiOiI0NWMyNDg0Yi0xOTgxLTQwYzQtOGI3MS02NmUzMmRiZjEwMDYiLCJzaWQiOiI3N2IzYTQwYy1kYTZkLTQ3NGEtODY3Ni05MDVlZGQyNTEyYzEiLCJCdWlsZElkIjoiOWVlNmQ0NzgtZDI4OC00N2Y3LWFhY2MtZjZlNmQwODJhZTZkOzQ5ODg2NSIsIm9yY2hpZCI6ImQ5MjM4MjQ2LTkzOTktNGM0ZS1iMTE4LTk4N2YzMmIwMDgyNS5ydW5fdGVzdF9wMV9fbGludXhfbXVzbF9hcm02NF9jaGVja2VkLl9fZGVmYXVsdCIsImlzcyI6ImFwcC52c3Rva2VuLnZpc3VhbHN0dWRpby5jb20iLCJhdWQiOiJhcHAudnN0b2tlbi52aXN1YWxzdHVkaW8uY29tfHZzbzpiNTVkZTRlZC00YjVhLTQyMTUtYThlNC0wYTBhNWY3MWU3ZDgiLCJuYmYiOjE1ODAxODk4ODksImV4cCI6MTU4MDIxNDQ4OX0.pQ_VufT_KXRWxxT_fKfe19EUhFWiumnkXoj-wwfW1q4XOvqm7cRq3jTnuKSHgUgkuDgpHD-zi6EKH6UK5BYCQm4liJ1n1FceXV2HnP-2v3G-CopJfRQ34sEhZOjeWVa3C9p88kdNynb_yW2EmRmWabCKgeP3iihukgYiRvBiuWR9uxlE7buM_-wNaEA_ICczzAfucYyLWGq6BvmBSgO3hA7CQ1kpq2YEMPjsUKy4c6qXgn1RzDOKORhGsta1UlGdGsbpkNebryY3wQ8OQbQSV3b_rpnBrwZfOd_PFlcsYZO_5FZFRTj1RxvCqprxZOEGrWFPHyBSfoULB4FNyZDlMA
2020-01-28 06:17:45,453: INFO: 548051863944: run(82): main: Main thread starting 10 workers
Worker 0: starting...
Worker 1: starting...
Worker 2: starting...
Worker 3: starting...
Worker 4: starting...
Worker 5: starting...
Worker 6: starting...
Worker 7: starting...
Worker 8: starting...
Worker 9: starting...
2020-01-28 06:17:45,456: INFO: 548051863944: run(89): main: Beginning reading of test results.
2020-01-28 06:17:45,457: INFO: 548051863944: run(95): main: Uploading results in batches of size 1000
2020-01-28 06:17:45,616: INFO: 548051863944: run(100): main: Main thread finished queueing batches
Searching '/root/helix/work/workitem/..' for log files
Generated log list: <ul></ul>
Searching '/root/helix/work/workitem' for test results files
Found results file /root/helix/work/workitem/testResults.xml with format xunit
Worker 0: uploaded 298 results
2020-01-28 06:17:52,670: INFO: 548051863944: run(104): main: Main thread exiting

Isn't this the Helix uploader?

I guess you wanted to see the XML file to see what it is parsing and trying to upload?

btw, immediately afterwards, there is this:

+ python /root/helix/work/correlation/xunit-reporter.py
Traceback (most recent call last):
  File "/root/helix/work/correlation/xunit-reporter.py", line 5, in <module>
    import helix.azure_storage
  File "/root/helix/scripts/helix/azure_storage.py", line 7, in <module>
    from azure.storage.blob import BlobClient, ContentSettings, ExponentialRetry
  File "/root/helix/scripts/azure/storage/blob/__init__.py", line 11, in <module>
    from ._blob_client import BlobClient
  File "/root/helix/scripts/azure/storage/blob/_blob_client.py", line 24, in <module>
    from ._shared.encryption import generate_blob_encryption_data
  File "/root/helix/scripts/azure/storage/blob/_shared/encryption.py", line 19, in <module>
    from cryptography.hazmat.primitives.padding import PKCS7
  File "/root/helix/scripts/cryptography/hazmat/primitives/padding.py", line 13, in <module>
    from cryptography.hazmat.bindings._padding import lib
ImportError: Error loading shared library ld-linux-aarch64.so.1: No such file or directory (needed by /root/helix/scripts/cryptography/hazmat/bindings/_padding.abi3.so)

which looks bad.

(fwiw, there is one other "Traceback" case in the log file, but it looks like that one possibly is expected -- it would be nice if there was some output to make that very explicit. Or, to suppress this "scary" output in this case.)

@BruceForstall
Copy link
Member Author

One of the AzDO logs shows:

Upload '/datadisks/disk1/workspace/_work/10/s/artifacts/log' to file container: '#/3313258/TestRunLogs_Linux_arm64_checked_jitstress

but I don't know where that ends up.

@MattGal
Copy link
Member

MattGal commented Jan 29, 2020

One of the AzDO logs shows:

Upload '/datadisks/disk1/workspace/_work/10/s/artifacts/log' to file container: '#/3313258/TestRunLogs_Linux_arm64_checked_jitstress

but I don't know where that ends up.

If we're talking about the most recent AzDO link you pasted, it's on the artifacts tab:
image

... if I'm mistaken and you're referencing a different pipeline execution, please share its link.

@BruceForstall
Copy link
Member Author

@MattGal Thanks -- the AzDO UI changed and I couldn't find the artifacts. Now I found them, so I see this. Obviously, this folder does not include any testResults.xml file.

The log file I referenced was: (1) download all log files (looks like there isn't a deep link into these), (2) "CoreCLR Pri1 Test Run Linux_musl arm64 checked" folder, (3) "19_Publish Logs.txt" file:

2020-01-28T06:44:08.1244635Z ##[section]Starting: Publish Logs
2020-01-28T06:44:08.1701786Z ==============================================================================
2020-01-28T06:44:08.1702443Z Task         : Publish build artifacts
2020-01-28T06:44:08.1702610Z Description  : Publish build artifacts to Azure Pipelines or a Windows file share
2020-01-28T06:44:08.1702727Z Version      : 1.158.1
2020-01-28T06:44:08.1702843Z Author       : Microsoft Corporation
2020-01-28T06:44:08.1703028Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/publish-build-artifacts
2020-01-28T06:44:08.1703174Z ==============================================================================
2020-01-28T06:44:10.0771482Z ##[section]Async Command Start: Upload Artifact
2020-01-28T06:44:10.0772037Z Uploading 15 files
2020-01-28T06:44:12.5768255Z File upload succeed.
2020-01-28T06:44:12.5769033Z Upload '/datadisks/disk1/workspace/_work/8/s/artifacts/log' to file container: '#/3313258/TestRunLogs_Linux_musl_arm64_checked_jitstress'
2020-01-28T06:44:13.4786894Z Associated artifact 7679856 with build 498865
2020-01-28T06:44:13.4788997Z ##[section]Async Command End: Upload Artifact
2020-01-28T06:44:13.4790420Z ##[section]Finishing: Publish Logs

So that's presumably how the log files from the machine invoking tests in Helix get updated.

From the Helix console log (above),

Searching '/root/helix/work/workitem' for test results files
Found results file /root/helix/work/workitem/testResults.xml with format xunit
Worker 0: uploaded 298 results
2020-01-28 06:17:52,670: INFO: 548051863944: run(104): main: Main thread exiting

Who is supposed to copy /root/helix/work/workitem/testResults.xml from the Helix client back to the /datadisks/disk1/workspace/_work/8/s/artifacts/log directory on the machine invoking Helix? (or some other location that will get uploaded to AzDO)

It looks like the answer is xunit-reporter.py, and that's the script that is crashing.

@BruceForstall
Copy link
Member Author

Ok, I ran manually and got a testRun.xml file (not sure who chooses this name or why it's not testResults.xml). For a particular failure case, I see:

    <collection total="1" passed="0" failed="1" skipped="0" name="Test collection for JIT_HardwareIntrinsics._X86_Sse2_X64_Sse2_X64_ro_Sse2_X64_ro_" time="1.109">
      <test name="JIT/HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.sh" type="JIT_HardwareIntrinsics._X86_Sse2_X64_Sse2_X64_ro_Sse2_X64_ro_" method="_X86_Sse2_X64_Sse2_X64_ro_Sse2_X64_ro_sh" time="1.1094756" result="Fail">
        <output><![CDATA[
Assert failure(PID 18592 [0x000048a0], Thread: 18592 [0x48a0]): Assertion failed 'type == lvaTable[lnum].lvType || (lvaIsImplicitByRefLocal(lnum) && fgGlobalMorph && (lvaTable[lnum].lvType == TYP_BYREF))' in 'JIT.HardwareIntrinsics.X86.Program:ConvertToUInt64Vector128UInt64()' (IL size 147)

    File: /home/bruce/gh/runtime/src/coreclr/src/jit/gentree.cpp Line: 6143
    Image: /home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/Tests/Core_Root/corerun

/home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/JIT/HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.sh: line 275: 18592 Aborted                 $LAUNCHER $ExePath "${CLRTestExecutionArguments[@]}"

Return code:      1
Raw output file:      /home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/JIT/HardwareIntrinsics/Reports/JIT.HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.output.txt
Raw output:
BEGIN EXECUTION
/home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/Tests/Core_Root//corerun Sse2.X64_ro.dll ''
Supported ISAs:
  AES:       False
  AVX:       False
  AVX2:      False
  BMI1:      False
  BMI2:      False
  FMA:       False
  LZCNT:     False
  PCLMULQDQ: False
  POPCNT:    False
  SSE:       False
  SSE2:      False
  SSE3:      False
  SSE4.1:    False
  SSE4.2:    False
  SSSE3:     False

Beginning test case ConvertToInt64.Vector128Double at 1/29/2020 9:18:47 AM
Random seed: 20010415; set environment variable CORECLR_SEED to this value to repro

Beginning scenario: RunUnsupportedScenario
Beginning scenario: RunBasicScenario_UnsafeRead

Ending test case at 1/29/2020 9:18:47 AM
Beginning test case ConvertToInt64.Vector128Int64 at 1/29/2020 9:18:47 AM
Random seed: 20010415; set environment variable CORECLR_SEED to this value to repro

Beginning scenario: RunUnsupportedScenario
Beginning scenario: RunBasicScenario_UnsafeRead

Ending test case at 1/29/2020 9:18:47 AM
Beginning test case ConvertToUInt64.Vector128UInt64 at 1/29/2020 9:18:47 AM
Random seed: 20010415; set environment variable CORECLR_SEED to this value to repro

Expected: 100
Actual: 134
END EXECUTION - FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=/home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/Tests/Core_Root/
> /home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/JIT/HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.sh
]]></output>
        <traits>
          <trait name="TestGroup" value="JIT.HardwareIntrinsics" />
        </traits>
        <failure exception-type="Xunit.Sdk.TrueException">
          <message><![CDATA[\nAssert failure(PID 18592 [0x000048a0], Thread: 18592 [0x48a0]): Assertion failed 'type == lvaTable[lnum].lvType || (lvaIsImplicitByRefLocal(lnum) && fgGlobalMorph && (lvaTable[lnum].lvType == TYP_BYREF))' in 'JIT.HardwareIntrinsics.X86.Program:ConvertToUInt64Vector128UInt64()' (IL size 147)\n\n    File: /home/bruce/gh/runtime/src/coreclr/src/jit/gentree.cpp Line: 6143\n    Image: /home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/Tests/Core_Root/corerun\n\n/home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/JIT/HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.sh: line 275: 18592 Aborted                 $LAUNCHER $ExePath \"${CLRTestExecutionArguments[@]}\"\n\nReturn code:      1\nRaw output file:      /home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/JIT/HardwareIntrinsics/Reports/JIT.HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.output.txt\nRaw output:\nBEGIN EXECUTION\n/home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/Tests/Core_Root//corerun Sse2.X64_ro.dll ''\nSupported ISAs:\n  AES:       False\n  AVX:       False\n  AVX2:      False\n  BMI1:      False\n  BMI2:      False\n  FMA:       False\n  LZCNT:     False\n  PCLMULQDQ: False\n  POPCNT:    False\n  SSE:       False\n  SSE2:      False\n  SSE3:      False\n  SSE4.1:    False\n  SSE4.2:    False\n  SSSE3:     False\n\nBeginning test case ConvertToInt64.Vector128Double at 1/29/2020 9:18:47 AM\nRandom seed: 20010415; set environment variable CORECLR_SEED to this value to repro\n\nBeginning scenario: RunUnsupportedScenario\nBeginning scenario: RunBasicScenario_UnsafeRead\n\nEnding test case at 1/29/2020 9:18:47 AM\nBeginning test case ConvertToInt64.Vector128Int64 at 1/29/2020 9:18:47 AM\nRandom seed: 20010415; set environment variable CORECLR_SEED to this value to repro\n\nBeginning scenario: RunUnsupportedScenario\nBeginning scenario: RunBasicScenario_UnsafeRead\n\nEnding test case at 1/29/2020 9:18:47 AM\nBeginning test case ConvertToUInt64.Vector128UInt64 at 1/29/2020 9:18:47 AM\nRandom seed: 20010415; set environment variable CORECLR_SEED to this value to repro\n\nExpected: 100\nActual: 134\nEND EXECUTION - FAILED\nTest Harness Exitcode is : 1\nTo run the test:\n> set CORE_ROOT=/home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/Tests/Core_Root/\n> /home/brucefo/build/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/JIT/HardwareIntrinsics/X86/Sse2.X64/Sse2.X64_ro/Sse2.X64_ro.sh\nExpected: True\nActual:   False]]></message>
          <stack-trace><![CDATA[   at JIT_HardwareIntrinsics._X86_Sse2_X64_Sse2_X64_ro_Sse2_X64_ro_._X86_Sse2_X64_Sse2_X64_ro_Sse2_X64_ro_sh() in /home/bruce/gh/runtime/artifacts/tests/coreclr/Linux.arm64.Checked/TestWrappers/JIT.HardwareIntrinsics/JIT.HardwareIntrinsics.XUnitWrapper.cs:line 20219]]></stack-trace>
        </failure>
      </test>
    </collection>

So while the "correct" text is there, the "escaped" failure message text that is used by the xunit.py parser (in run.py) is apparently coming from <failure exception-type="Xunit.Sdk.TrueException">. So perhaps whichever xunit we're using is doing this?

One workaround would be to use the <output> node instead of the <message> node inside <failure>.

The other avenue is to figure out why xunit (?) is doing this newline escaping.

Comments?

@BruceForstall
Copy link
Member Author

@ViktorHofer Looks like you've worked on the xunit console runner. Do we still use the one in the arcade repo?

Assuming we use the xunit from https://github.com/xunit/xunit (or some close cousin), the answer seems to be in src\xunit.runner.utility\Visitors\XmlTestExecutionVisitor.cs:

static XElement CreateFailureElement(IFailureInformation failureInfo)
{
    return new XElement("failure",
        new XAttribute("exception-type", failureInfo.ExceptionTypes[0]),
        new XElement("message", new XCData(XmlEscape(ExceptionUtility.CombineMessages(failureInfo)))),
        new XElement("stack-trace", new XCData(ExceptionUtility.CombineStackTraces(failureInfo) ?? string.Empty))
    );
}

static string Escape(string value)
{
    if (value == null)
        return string.Empty;

    return value.Replace("\\", "\\\\")
                .Replace("\r", "\\r")
                .Replace("\n", "\\n")
                .Replace("\t", "\\t")
                .Replace("\0", "\\0")
                .Replace("\a", "\\a")
                .Replace("\b", "\\b")
                .Replace("\v", "\\v")
                .Replace("\"", "\\\"")
                .Replace("\f", "\\f");
}

/// <summary>
/// Escapes a string for placing into the XML.
/// </summary>
/// <param name="value">The value to be escaped.</param>
/// <returns>The escaped value.</returns>
protected static string XmlEscape(string value)
{
    if (value == null)
        return string.Empty;

    value = Escape(value);
    var escapedValue = new StringBuilder(value.Length);
    for (var idx = 0; idx < value.Length; ++idx)
    {
        char ch = value[idx];
        if (ch < 32)
            escapedValue.Append($@"\x{(+ch).ToString("x2")}");
        else if (char.IsSurrogatePair(value, idx)) // Takes care of the case when idx + 1 == value.Length
        {
            escapedValue.Append(ch); // Append valid surrogate chars like normal
            escapedValue.Append(value[++idx]);
        }
        // Check for invalid chars and append them like \x----
        else if (char.IsSurrogate(ch) || ch == '\uFFFE' || ch == '\uFFFF')
            escapedValue.Append($@"\x{(+ch).ToString("x4")}");
        else
            escapedValue.Append(ch);
    }

    return escapedValue.ToString();
}

Interestingly, in that same file, when creating the "output" item (also a CDATA), it uses (in CreateTestResultElement()):

testResultElement.Add(new XElement("output", new XCData(testResult.Output)));          

so, no XmlEscape().

Maybe none of the CDATA elements should use XmlEscape()?

I would suggest simply un-escaping this in the xunit.py script that is parsing these, but that has the potential to corrupt legal pre-existing cases of \r or \n characters in the text (e.g., if there was a \root\runtime\next pathname in the original source).

@alexperovich
Copy link
Member

We could unescape them, but I don't like it messing up paths and other places \r or \n shows up. A CDATA section shouldn't have any escaping in it at all. Newlines in xml don't even need to be escaped. Even attribute values can have literal newlines in them.

I don't think the xunit console runner is in active development so a change there would be hard to get published. If you can switch to using dotnet vstest and output trx format that would not have this problem IIRC.

@ViktorHofer
Copy link
Member

We use the Microsoft.DotNet.XUnitConsoleRunner which lives in Arcade for netcoreapp runs. This is only the runner, so sources from xunit.runner.utility are not fixable in Arcade but in xunit/xunit.

We plan to switch to dotnet test but there are still blockers ahead. I need to come up with a plan for that.

@jmarolf
Copy link

jmarolf commented Jun 29, 2020

+1 for wanting a fix for this. Makes looking at test output for new contributors a terrible experience. If dotnet test is months away can we please find a temporary fix for this?

@ViktorHofer
Copy link
Member

ViktorHofer commented Jul 12, 2020

The dotnet test migration is unblocked hence I hope we switch to it sooner than later: #37953. Note that the issue only tracks the libraries migration to dotnet test.

@ViktorHofer ViktorHofer removed the untriaged New issue has not been triaged by the area owner label Jul 12, 2020
@ViktorHofer ViktorHofer modified the milestone: 5.0.0 Jul 12, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Status: No status
Development

No branches or pull requests

10 participants