Illegal xml characters in data to be logged block log creation

[Alikont]

Hello, I'm trying to use junit test logger for building and uploading results from inside dotnet/sdk:6.0 container.

When I run test command

dotnet test --logger:"junit;LogFilePath=test-result.xml"

Tests are run but no test-result.xml file is created.

It works fine if run from Windows

When I run it with -d diag.log and inspect log file I've noticed strange exception related to junit logger

TpTrace Error: 0 : 2176, 4, 2022/11/01, 01:40:56.788, 10717012278100, vstest.console.dll, MulticastDelegateUtilities.SafeInvoke: 1: Invoking callback 2/Spekt.TestLogger.Core.TestRunBuilder for <Subscribe>b__5_3.InternalTestLoggerEvents.SendTestRunComplete, failed after 10 ms with: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation.
 ---> System.ArgumentException: '', hexadecimal value 0x1B, is an invalid character.
   at System.Xml.XmlEncodedRawTextWriter.WriteElementTextBlock(Char* pSrc, Char* pSrcEnd)
   at System.Xml.XmlEncodedRawTextWriter.WriteString(String text)
   at System.Xml.XmlEncodedRawTextWriterIndent.WriteString(String text)
   at System.Xml.XmlWellFormedWriter.WriteString(String text)
   at System.Xml.Linq.ElementWriter.WriteElement(XElement e)
   at System.Xml.Linq.XElement.WriteTo(XmlWriter writer)
   at System.Xml.Linq.XContainer.WriteContentTo(XmlWriter writer)
   at System.Xml.Linq.XNode.GetXmlString(SaveOptions o)
   at System.Xml.Linq.XNode.ToString()
   at Microsoft.VisualStudio.TestPlatform.Extension.Junit.Xml.TestLogger.JunitXmlSerializer.Serialize(LoggerConfiguration loggerConfiguration, TestRunConfiguration runConfiguration, List`1 results, List`1 messages)
   at Spekt.TestLogger.Core.TestRunCompleteWorkflow.Complete(ITestRun testRun, TestRunCompleteEventArgs completeEvent) in /home/runner/work/testlogger/testlogger/src/TestLogger/Core/TestRunCompleteWorkflow.cs:line 38
   at Spekt.TestLogger.Core.TestRunBuilder.<Subscribe>b__5_3(Object _, TestRunCompleteEventArgs eventArgs) in /home/runner/work/testlogger/testlogger/src/TestLogger/Core/TestRunBuilder.cs:line 55
   --- End of inner exception stack trace ---
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Span`1& arguments, Signature sig, Boolean constructor, Boolean wrapExceptions)
   at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
   at System.Delegate.DynamicInvokeImpl(Object[] args)
   at System.Delegate.DynamicInvoke(Object[] args)
   at Microsoft.VisualStudio.TestPlatform.Utilities.MulticastDelegateUtilities.SafeInvoke(Delegate delegates, Object sender, Object args, String traceDisplayName).

My csproj packages

  <ItemGroup>
    <PackageReference Include="Microsoft.AspNetCore.Mvc.Testing" Version="6.0.8" />
    <PackageReference Include="Microsoft.EntityFrameworkCore.InMemory" Version="6.0.8" />
    <PackageReference Include="Microsoft.NET.Test.Sdk" Version="17.1.0" />
    <PackageReference Include="MSTest.TestAdapter" Version="2.2.8" />
    <PackageReference Include="MSTest.TestFramework" Version="2.2.8" />
    <PackageReference Include="coverlet.collector" Version="3.1.2" />
    <PackageReference Include="JunitXml.TestLogger" Version="3.0.114" />
  </ItemGroup>

[Siphonophora]

i was able to repro this on windows. 0x1F isn't legal in xml, so I assume it must not be sent to the logger when you run tests on windows.

After some reading, it doesn't look like the standard library provides an option to escape characters that aren't legal. I'm not sure how we would want to do that. @codito thoughts?

    [Test]
    public void XmlTest()
    {
        XmlSerializer ser = new XmlSerializer(typeof(XmlNode));
        XmlNode myNode = new XmlDocument().
        CreateNode(XmlNodeType.Element, "MyNode", "ns");
        byte[] data = new byte[] { 0x1F };
        string ascii = Encoding.ASCII.GetString(data);
        myNode.InnerText = $"Hello Node {ascii}";
        TextWriter writer = new StreamWriter("c:\\temp\\invalid.xml");
        ser.Serialize(writer, myNode);
        writer.Close();
    }

'', hexadecimal value 0x1F, is an invalid character.

   at System.Xml.XmlEncodedRawTextWriter.WriteElementTextBlock(Char* pSrc, Char* pSrcEnd)
   at System.Xml.XmlEncodedRawTextWriter.WriteString(String text)
   at System.Xml.XmlWellFormedWriter.WriteString(String text)
   at System.Xml.XmlText.WriteTo(XmlWriter w)
   at System.Xml.XmlElement.WriteElementTo(XmlWriter writer, XmlElement el)
   at System.Xml.XmlElement.WriteTo(XmlWriter w)
   at System.Xml.Serialization.XmlSerializationWriter.WriteElement(XmlNode node, String name, String ns, Boolean isNullable, Boolean any)
   at Microsoft.Xml.Serialization.GeneratedAssembly.XmlSerializationWriterXmlNode.Write1_Item(Object o)

[Siphonophora]

@Alikont I'm still not sure how we would approach fixing this. Do you think its going to be a persistent issue?

[Alikont]

The XML writer just checks the character code as invalid

https://source.dot.net/#System.Private.Xml/System/Xml/Core/XmlEncodedRawTextWriter.cs,1107

So there is not a lot that can be done on XML side of things.

The more interesting question is how this character even appears in the data, maybe it's better to escape/filter them on the emitter side of things? Maybe some stdout input generates some broken characters so it should be filtered there on capture?

[mbaturin-rubbi]

If you have a similar error, make sure that your console output does not contain colors.

I encountered this problem when using a logger created by LoggerFactory.Create(y => y.AddConsole()); . By default logger highlights the message type. I got the same error.

In my case, logger was replaced with LoggerFactory.Create(y => y.AddSimpleConsole(options => options.ColorBehavior = LoggerColorBehavior.Disabled));

[merlinschumacher]

I have the same issue on a Windows system without Docker. I use Nlog for logging.

[Siphonophora]

@Alikont @jairbubbles @merlinschumacher

It seems clear this isn't a one-off issue. While @mbaturin-bars has shown this can sometimes have to do with how your console output is produced, I realize the illegal characters may sometimes be intended.

I see a few problems:

1. As far as I can tell, the core library for xml writing isn't going to handle this.
2. We can't just throw out illegal characters because we have no way to know if they are intended. And I don't think this is common enough to warrant some kind feature flags / user customized behavior.
3. I'm not aware of a standard way to handle this. In principal I think we would need to do some encoding like abc?123 where the ? is illegal to become abc0x1F123. That said I see this as immediately having issues with clarity about what is and isn't encoded. Encoding the entire string containing any illegal characters seems worse is a way, given these logs are supposed to be human readable.

So, I would appreciate input from any of you.

@codito I see no reason why this wouldn't happen in the other users so I'm thinking the solution would have to be in the core logger. Whatever it is.

[jairbubbles]

In my case I didn't really care about the log, it was related to a very specific git command output (git status -- porcelain -z) and this output is not meant to be read by humans.

So if the characters were just dismissed it would have been totally fine, not having a result file created at all was very disturbing, it took me time to figure out what was going on. A warning message could be returned to indicate some illegal characters were thrown out.

[codito]

@Siphonophora we've to replace the invalid xml characters. Let's provide an utility in TestLogger core and use it in the loggers. What do you think?

E.g. the TrxLogger inbuilt in dotnet test does it here.

[Siphonophora]

@codito Having the pattern from TRX to follow is great. Thanks for pointing that out. The unicode escaping seems like a solid plan

I will try to dig into it soon and will ping when I have something in the core library.

[gregsdennis]

I think I'm also experiencing this when running the JSON Schema Test Suite, which definitely tests for odd characters.

I particularly care about the log file as I have test counts as a badge in my readme. I have to collate a bunch of test result files and sum the counts. Because this one file is not generating, it's indicating about 20,000 tests short of the real number.

Honestly, I care less about the actual test results as long as I can get a total tests run. GH Actions is pretty good at capturing output.

[codito]

Fix is work in progress here: https://github.com/spekt/testlogger/pull/37

[msrouchou]

Hello, I wanted to kindly bring attention that the pull request is merged but not released yet. Considering the importance and value these changes bring (after I have spent a day debugging the sudden disappearance of a reports file ^^), I would like to suggest and urge that we proceed with a release. Thanks!

[codito]

@msrouchou thanks for the nudge. Just pushed https://www.nuget.org/packages/JunitXml.TestLogger/3.0.125

[codito]

Latest release is https://github.com/spekt/junit.testlogger/releases/tag/v3.0.134 and https://www.nuget.org/packages/JunitXml.TestLogger/3.0.134. Please try the fix.