Mangled test output regression after problematic fix

[egraff]

Present in NUnit3TestAdapter 4.3.0 and newer.

Description

When printing full file paths for a collection of DLLs on Windows, I found that after the string \u has been printed to the test output, subsequent test output would be mangled.

Minimal test case:

TestContext.Out.WriteLine("UMMM {0}", "b\\3597805");
TestContext.Out.WriteLine("C:\\Windows\\System32\\user32.dll");
TestContext.Out.WriteLine("UMMM {0}", "b\\3597805");

Resulting output:

UMMM b\3597805
C:\Windows\System32\user32.dll
UMMM b奸05

Expected output:

UMMM b\3597805
C:\Windows\System32\user32.dll
UMMM b\3597805

Cause

I've found that it's likely caused by this commit: https://github.com/nunit/nunit3-vs-adapter/commit/6a6e422a7b4874a2340e90b41f9e9a12b3d3a450 (https://github.com/nunit/nunit3-vs-adapter/pull/984).

I've not delved into the details of that commit, but it's clear that there is a problem that needs fixing.

[OsirisTerje]

Can you enable the Dump feature (runsettings) and check if the xml from the framework/engine appends that character, or see what is actually present there. That way we can see if this is adapter or engine/framework.

[egraff]

@OsirisTerje sure 🙂 I already verified that the problem was with the adapter, though, by changing the package version. The problem was not present in 4.2.1, but has been present in all versions since 4.3.0.

Anyways, running dotnet test -v n --logger "console;verbosity=normal" -- "NUnit.DumpXmlTestResults=true", I get this in the .dump file (only pasting the relevant section):

      <test-suite type='TestSuite' id='0-1003' name='TestProject2' fullname='TestProject2' runstate='Runnable' testcasecount='1' result='Passed' start-time='2023-09-20T14:10:15.2894068Z' end-time='2023-09-20T14:10:15.2990287Z' duration='0.009621' total='1' passed='1' failed='0' warnings='0' inconclusive='0' skipped='0' asserts='0'>
         <test-suite type='TestFixture' id='0-1000' name='Tests' fullname='TestProject2.Tests' classname='TestProject2.Tests' runstate='Runnable' testcasecount='1' result='Passed' start-time='2023-09-20T14:10:15.2905973Z' end-time='2023-09-20T14:10:15.2986402Z' duration='0.008043' total='1' passed='1' failed='0' warnings='0' inconclusive='0' skipped='0' asserts='0'>
            <test-case id='0-1001' name='Test1' fullname='TestProject2.Tests.Test1' methodname='Test1' classname='TestProject2.Tests' runstate='Runnable' seed='1895503531' result='Passed' start-time='2023-09-20T14:10:15.2922751Z' end-time='2023-09-20T14:10:15.2959240Z' duration='0.003737' asserts='0'>
               <output><![CDATA[UMMM b\3597805
C:\Windows\System32\user32.dll
UMMM b\3597805
]]></output>
            </test-case>
         </test-suite>
      </test-suite>

[OsirisTerje]

@egraff Since you have already found where the error happens, could you do a PR for this? There are already some tests around the former issue, so you could just add to them.

[egraff]

@OsirisTerje well, even though I found where the problem is, I don't know how to fix it in a satisfactory way - that seems much more complicated. The problem is that IMO the PR/feature that introduced this bug is fundamentally broken, and should be reverted. But ideally, a fix would try to preserve the idea of what the feature was supposed to be - but that is essentially trying to re-invent a way to achieve that feature without adverse side-effects to the test output.

[egraff]

@OsirisTerje having though about this some more, I think the right fix - considering the NUnit3TestAdapter is a separate project (and nuget) from the framework/engine - is to revert the aforementioned changeset after all!

The author did have a well thought through evaluation (here: https://github.com/nunit/nunit/issues/4126#issuecomment-1152995943) of different options for fixing https://github.com/nunit/nunit/issues/4126, but just (IMHO) landed on the wrong option in the end.

My assertion is that it is not possible to fix https://github.com/nunit/nunit/issues/4126 in the test adapter, because by the time the NUnit framework has escaped the color control characters in EscapeInvalidXmlCharacters, it's too late to determine which parts of the output went through this particular code path (and we'd like to un-escape), and which parts are strings that are deliberately escaped by the test code or application-under-test or simply resembles escaped character sequences. I don't believe any sort of logic or heuristics can accurately decide which is which, and I therefore think that the only viable option to fix this properly is to do it with a breaking change in the NUnit framework.

@Socolin being the original author of the issue and following fix, do you have any thoughts on this?

[Socolin]

For me it seems that if some things are escaped with \ then all \ should also be escaped \\ to know when this is an escape marker and when it's an \

I agree with the fact that if only some parts are escaped and not the other then we will have a hard time knowing what can be escape or not. And I think this task should be left to the serializer alone and there should not have any custom escaping before and custom un-escaping after.

To resolve the issue I see 2 solutions right now:

1. I could update the code that unescape the color code to do something more precise and only unescape the ANSI code. Parsing the ANSI codes are trivial, so I could detect it before un-escaping it. It's \ESC then [ and it end with m with commands (numbers) separated with ; in the middle (https://en.wikipedia.org/wiki/ANSI_escape_code#SGR_(Select_Graphic_Rendition)_parameters)

   Example:

   \ESC[38;2;255;0;0;1;48;2;0;0;255m Will set font color 38 to rgb 2 red 255;0;0 in bold 1 and background color 48 to rgb 2 to blue 0;0;255 \ESC[0m Will reset everything

2. Remove completely the logic of escape / un-escape and let the serialize do its job

   • I really don't know if it's something that can be change at this point.
   • I certainly miss something here and the escape code probably have a good reason to exists. I'm curious to know about it if anyone have this knowledge
     • If it was escaped for readability, IMHO it's the responsibility of the thing that display if to arrange it and not the part that store the data to make it readable.

Let me know if I can help with this

[OsirisTerje]

@Socolin If the tests are augmented by the examples from @egraff , and possibly more, that should be enough to ensure that the suggested fix would work. It would be awesome if you could help out with this.

[Socolin]

@Socolin If the tests are augmented by the examples from @egraff , and possibly more, that should be enough to ensure that the suggested fix would work. It would be awesome if you could help out with this.

Ok, I'll do a PR when I find some times, was the code reverted ? or are we waiting after the fix ? (To help me prioritize this)

[OsirisTerje]

The code is not reverted. Better if you can fix this .

[Socolin]

I created a PR https://github.com/nunit/nunit3-vs-adapter/pull/1147