Skip to content

Commit 78539ec

Browse files
nohwndCopilot
andauthored
[fix] Fix tilde/exclamation characters corrupted in TerminalLogger test output (#16046)
* Fix tilde/exclamation characters corrupted in TerminalLogger output When test output contained sequences of 4+ tilde characters (~~~~) or 4+ exclamation marks ( { echo ___BEGIN___COMMAND_OUTPUT_MARKER___; PS1=;PS2=;unset HISTFILE; EC=0; echo ___BEGIN___COMMAND_DONE_MARKER___0; } { echo ___BEGIN___COMMAND_OUTPUT_MARKER___; PS1=;PS2=;unset HISTFILE; EC=0; echo ___BEGIN___COMMAND_DONE_MARKER___0; }), the MSBuildLogger.Escape method would replace them with underscores (____) before applying the actual CR/LF encoding. This caused any ~~ or { echo ___BEGIN___COMMAND_OUTPUT_MARKER___; PS1=;PS2=;unset HISTFILE; EC=0; echo ___BEGIN___COMMAND_DONE_MARKER___0; } sequences in test names, assertion messages, or stack traces to appear corrupted in the terminal logger. Root cause: the old encoding used ~~~~ as a CR placeholder and { echo ___BEGIN___COMMAND_OUTPUT_MARKER___; PS1=;PS2=;unset HISTFILE; EC=0; echo ___BEGIN___COMMAND_DONE_MARKER___0; } { echo ___BEGIN___COMMAND_OUTPUT_MARKER___; PS1=;PS2=;unset HISTFILE; EC=0; echo ___BEGIN___COMMAND_DONE_MARKER___0; } as an LF placeholder, and sanitized input by pre-replacing those sequences with ____. This sanitization destructively modified user data. Fix: Use ASCII control characters STX (\x02) for CR and ETX (\x03) for LF as the escape sequences. These control characters cannot appear in normal test output (test names, assertion messages, stack traces), so no sanitization of user data is needed. Fixes #15268 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * test: add encoder/decoder round-trip tests for MSBuildLogger Add MSBuildLoggerEncoderTests with four round-trip tests that call MSBuildLogger.FormatMessage() (encoder) and then decode the result using the same logic as VSTestTask2.TryGetMessage (decoder), verifying that tilde chars, exclamation chars, newlines, and multiple fields all survive the full encode/decode cycle. Make FormatMessage internal (was private) to allow access from the vstest.console.UnitTests project via InternalsVisibleTo. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Address review: add sync warning to Decode helper and cross-reference encoder tests Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Use %-escaping instead of control chars for MSBuild logger encoding The control char approach (\x02, \x03) from the previous commit is not readable in MSBuild binary logs. Switch to %-escaping (like URL encoding): % -> %% | -> %p \r -> %r \n -> %n This also fixes the remaining lossy ||||->____ replacement. Pipes in user data are now escaped as %p and round-trip correctly. The decoder must be a single-pass scanner, not chained Replace calls. Chained Replace would decode %%n as %+newline instead of literal %n — the %% replacement would not protect the following char from the %n replacement. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * test: add e2e test for special char encoding in TerminalLogger output Add FailingTestWithSpecialChars to TerminalLoggerTestProject that puts ~~~~~!!!!||||%n in an assertion message. The e2e test in DotnetTestMSBuildOutputTests verifies these characters survive the MSBuildLogger encoding round-trip through dotnet test with -tl:on. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Fix review comments: doc, boxing in Unescape Fix XML doc example that showed message names with parameter count suffix (run-start1, test-failed6) which was never emitted by the code. Replace switch expression in Unescape with switch statement to avoid char/string type mixing that causes boxing via StringBuilder.Append(object). Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent 617f549 commit 78539ec

6 files changed

Lines changed: 284 additions & 12 deletions

File tree

src/Microsoft.TestPlatform.Build/Tasks/VSTestTask2.cs

Lines changed: 36 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -265,7 +265,7 @@ private bool TryGetMessage(string singleLine, out string name, out string?[] dat
265265
{
266266
var parts = singleLine.Split(_messageSplitterArray, StringSplitOptions.None);
267267
name = parts[1];
268-
data = parts.Skip(2).Take(parts.Length).Select(p => p?.Replace("~~~~", "\r").Replace("!!!!", "\n")).ToArray();
268+
data = parts.Skip(2).Take(parts.Length).Select(Unescape).ToArray();
269269
return true;
270270
}
271271

@@ -274,6 +274,41 @@ private bool TryGetMessage(string singleLine, out string name, out string?[] dat
274274
return false;
275275
}
276276

277+
/// <summary>
278+
/// Reverses MSBuildLogger.Escape. Single-pass scanner to correctly handle
279+
/// sequences like <c>%%n</c> (literal <c>%n</c>, not <c>%</c> + newline).
280+
/// </summary>
281+
private static string? Unescape(string? input)
282+
{
283+
if (input == null)
284+
{
285+
return null;
286+
}
287+
288+
var sb = new StringBuilder(input.Length);
289+
for (int i = 0; i < input.Length; i++)
290+
{
291+
if (input[i] == '%' && i + 1 < input.Length)
292+
{
293+
char next = input[++i];
294+
switch (next)
295+
{
296+
case '%': sb.Append('%'); break;
297+
case 'p': sb.Append('|'); break;
298+
case 'r': sb.Append('\r'); break;
299+
case 'n': sb.Append('\n'); break;
300+
default: sb.Append('%'); sb.Append(next); break;
301+
}
302+
}
303+
else
304+
{
305+
sb.Append(input[i]);
306+
}
307+
}
308+
309+
return sb.ToString();
310+
}
311+
277312
protected override string? GenerateCommandLineCommands()
278313
{
279314
return TestTaskUtils.CreateCommandLineArguments(this);

src/vstest.console/Internal/MSBuildLogger.cs

Lines changed: 48 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -229,11 +229,12 @@ private void TestResultHandler(object? sender, TestResultEventArgs e)
229229
}
230230

231231
/// <summary>
232-
/// Writes message to standard output, with the name of the message followed by the number of
233-
/// parameters. With each parameter delimited by '||||', and newlines replaced with ~~~~ and !!!!.
232+
/// Writes message to standard output, with the name of the message followed by
233+
/// parameters. Each parameter is delimited by '||||', and special characters are
234+
/// escaped with '%' (see <see cref="Escape"/>).
234235
/// Such as:
235-
/// ||||run-start1||||s:\t\mstest97\bin\Debug\net8.0\mstest97.dll
236-
/// ||||test-failed6||||TestMethod5||||Assert.IsTrue failed. |||| at mstest97.UnitTest1.TestMethod5() in s:\t\mstest97\UnitTest1.cs:line 27~~~~!!!! at Syste...
236+
/// ||||run-start||||s:\t\mstest97\bin\Debug\net8.0\mstest97.dll
237+
/// ||||test-failed||||TestMethod5||||Assert.IsTrue failed. |||| at mstest97.UnitTest1.TestMethod5() in s:\t\mstest97\UnitTest1.cs:line 27%r%n at Syste...
237238
/// </summary>
238239
/// <param name="name"></param>
239240
/// <param name="data"></param>
@@ -246,7 +247,7 @@ private static void SendMessage(string name, params string?[] data)
246247
Output.Information(appendPrefix: false, message);
247248
}
248249

249-
private static string FormatMessage(string name, params string?[] data)
250+
internal static string FormatMessage(string name, params string?[] data)
250251
{
251252
return $"||||{name}||||{string.Join("||||", data.Select(Escape))}";
252253
}
@@ -258,11 +259,49 @@ private static string FormatMessage(string name, params string?[] data)
258259
return null;
259260
}
260261

262+
// '%'-based escaping: escape the escape char first, then special chars.
263+
// This is lossless (unlike the old ||||→____ replacement) and stays readable
264+
// in MSBuild binary logs (unlike \x02/\x03 control chars).
261265
return input
262-
// Cleanup characters that we are using ourselves to delimit the message
263-
.Replace("||||", "____").Replace("~~~~", "____").Replace("!!!!", "____")
264-
// Replace new line characters that would change how the message is consumed.
265-
.Replace("\r", "~~~~").Replace("\n", "!!!!");
266+
.Replace("%", "%%")
267+
.Replace("|", "%p")
268+
.Replace("\r", "%r")
269+
.Replace("\n", "%n");
270+
}
271+
272+
/// <summary>
273+
/// Reverses <see cref="Escape"/>. Must be a single-pass scanner — chained Replace
274+
/// would incorrectly decode <c>%%n</c> as <c>%\n</c> instead of <c>%n</c>.
275+
/// </summary>
276+
internal static string? Unescape(string? input)
277+
{
278+
if (input == null)
279+
{
280+
return null;
281+
}
282+
283+
var sb = new StringBuilder(input.Length);
284+
for (int i = 0; i < input.Length; i++)
285+
{
286+
if (input[i] == '%' && i + 1 < input.Length)
287+
{
288+
char next = input[++i];
289+
switch (next)
290+
{
291+
case '%': sb.Append('%'); break;
292+
case 'p': sb.Append('|'); break;
293+
case 'r': sb.Append('\r'); break;
294+
case 'n': sb.Append('\n'); break;
295+
default: sb.Append('%'); sb.Append(next); break;
296+
}
297+
}
298+
else
299+
{
300+
sb.Append(input[i]);
301+
}
302+
}
303+
304+
return sb.ToString();
266305
}
267306

268307
/// <summary>

test/Microsoft.TestPlatform.Acceptance.IntegrationTests/DotnetTestMSBuildOutputTests.cs

Lines changed: 10 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,14 @@ public void MSBuildLoggerCanBeEnabledByBuildPropertyAndDoesNotEatSpecialChars(Ru
3939
StdOutputContains("FailingTest (");
4040
StdOutputContains("Expected: \"ğğğ𦮙我們剛才從𓋴𓅓𓏏𓇏𓇌𓀀\"");
4141
StdOutputContains("at TerminalLoggerUnitTests.UnitTest1.FailingTest() in");
42+
43+
// Verify that ~, !, |, and % characters in test output survive the MSBuildLogger encoding round-trip.
44+
StdOutputContains("FailingTestWithSpecialChars (");
45+
StdOutputContains("~~~~~");
46+
StdOutputContains("!!!!");
47+
StdOutputContains("||||");
48+
StdOutputContains("%n");
49+
4250
// We are sending those as low prio messages, they won't show up on screen but will be in binlog.
4351
//StdOutputContains("passed PassingTest");
4452
//StdOutputContains("skipped SkippingTest");
@@ -57,7 +65,7 @@ public void MSBuildLoggerCanBeDisabledByBuildProperty(RunnerInfo runnerInfo)
5765
InvokeDotnetTest($@"{projectPath} -nodereuse:false /p:VsTestUseMSBuildOutput=false /p:PackageVersion={IntegrationTestEnvironment.LatestLocallyBuiltNugetVersion}", workingDirectory: Path.GetDirectoryName(projectPath));
5866

5967
// Check that we see the summary that is printed from the console logger, meaning the new output is disabled.
60-
StdOutputContains("Failed! - Failed: 1, Passed: 1, Skipped: 1, Total: 3, Duration:");
68+
StdOutputContains("Failed! - Failed: 2, Passed: 1, Skipped: 1, Total: 4, Duration:");
6169
// We are sending those as low prio messages, they won't show up on screen but will be in binlog.
6270
//StdOutputContains("passed PassingTest");
6371
//StdOutputContains("skipped SkippingTest");
@@ -77,7 +85,7 @@ public void MSBuildLoggerCanBeDisabledByEnvironmentVariableProperty(RunnerInfo r
7785
InvokeDotnetTest($@"{projectPath} -nodereuse:false /p:PackageVersion={IntegrationTestEnvironment.LatestLocallyBuiltNugetVersion}", environmentVariables: new Dictionary<string, string?> { ["MSBUILDENSURESTDOUTFORTASKPROCESSES"] = "1" }, workingDirectory: Path.GetDirectoryName(projectPath));
7886

7987
// Check that we see the summary that is printed from the console logger, meaning the new output is disabled.
80-
StdOutputContains("Failed! - Failed: 1, Passed: 1, Skipped: 1, Total: 3, Duration:");
88+
StdOutputContains("Failed! - Failed: 2, Passed: 1, Skipped: 1, Total: 4, Duration:");
8189

8290
ExitCodeEquals(1);
8391
}

test/Microsoft.TestPlatform.Build.UnitTests/VSTestTask2RegressionTests.cs

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -175,6 +175,76 @@ public void LogEventsFromTextOutput_NullOutput_ShouldNotThrow()
175175
task.TestLogEventsFromTextOutput("||||output-info||||", MessageImportance.High);
176176
}
177177

178+
[TestMethod]
179+
public void LogEventsFromTextOutput_TestFailed_TildeCharsInMessage_ShouldNotBeCorrupted()
180+
{
181+
var task = CreateVSTestTask2();
182+
var engine = (RecordingBuildEngine)task.BuildEngine;
183+
184+
// 5 tilde chars — the old encoding replaced ~~~~ (4 tildes) with ____
185+
var tildeString = new string('~', 5);
186+
task.TestLogEventsFromTextOutput($"||||test-failed||||{tildeString}||||TestFile.cs||||42", MessageImportance.High);
187+
188+
Assert.HasCount(1, engine.Errors);
189+
Assert.Contains(tildeString, engine.Errors[0].Message ?? string.Empty);
190+
}
191+
192+
[TestMethod]
193+
public void LogEventsFromTextOutput_TestFailed_ExclamationCharsInMessage_ShouldNotBeCorrupted()
194+
{
195+
var task = CreateVSTestTask2();
196+
var engine = (RecordingBuildEngine)task.BuildEngine;
197+
198+
// 4 exclamation marks — the old encoding replaced !!!! (4 bangs) with ____
199+
var bangString = new string('!', 4);
200+
task.TestLogEventsFromTextOutput($"||||test-failed||||{bangString}||||TestFile.cs||||42", MessageImportance.High);
201+
202+
Assert.HasCount(1, engine.Errors);
203+
Assert.Contains(bangString, engine.Errors[0].Message ?? string.Empty);
204+
}
205+
206+
[TestMethod]
207+
public void LogEventsFromTextOutput_TestFailed_NewlinesEncodedWithPercentEscapes_ShouldBeRestored()
208+
{
209+
var task = CreateVSTestTask2();
210+
var engine = (RecordingBuildEngine)task.BuildEngine;
211+
212+
// Simulate what MSBuildLogger.Escape produces: \r → %r, \n → %n
213+
var messageWithNewlines = "Assert failed%r%n at MyTest()";
214+
task.TestLogEventsFromTextOutput($"||||test-failed||||{messageWithNewlines}||||TestFile.cs||||42", MessageImportance.High);
215+
216+
Assert.HasCount(1, engine.Errors);
217+
Assert.Contains("Assert failed\r\n at MyTest()", engine.Errors[0].Message ?? string.Empty);
218+
}
219+
220+
[TestMethod]
221+
public void LogEventsFromTextOutput_TestFailed_PipesInMessage_ShouldNotBreakParsing()
222+
{
223+
var task = CreateVSTestTask2();
224+
var engine = (RecordingBuildEngine)task.BuildEngine;
225+
226+
// Pipes are escaped as %p by MSBuildLogger.Escape, so they can't break the |||| delimiter.
227+
var messageWithPipes = "expected: a]%p%p%p%p[b";
228+
task.TestLogEventsFromTextOutput($"||||test-failed||||{messageWithPipes}||||TestFile.cs||||42", MessageImportance.High);
229+
230+
Assert.HasCount(1, engine.Errors);
231+
Assert.Contains("expected: a]||||[b", engine.Errors[0].Message ?? string.Empty);
232+
}
233+
234+
[TestMethod]
235+
public void LogEventsFromTextOutput_TestFailed_PercentInMessage_ShouldNotBeCorrupted()
236+
{
237+
var task = CreateVSTestTask2();
238+
var engine = (RecordingBuildEngine)task.BuildEngine;
239+
240+
// %% is the escape for literal %, and %%n must decode to %n not to %+newline.
241+
var messageWithPercent = "100%%%% done %%n not a newline";
242+
task.TestLogEventsFromTextOutput($"||||test-failed||||{messageWithPercent}||||TestFile.cs||||42", MessageImportance.High);
243+
244+
Assert.HasCount(1, engine.Errors);
245+
Assert.Contains("100%% done %n not a newline", engine.Errors[0].Message ?? string.Empty);
246+
}
247+
178248
private static TestableVSTestTask2 CreateVSTestTask2()
179249
{
180250
var engine = new RecordingBuildEngine();

test/TestAssets/TerminalLoggerTestProject/UnitTest1.cs

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,20 @@ public void FailingTest()
3535
#pragma warning restore MSTEST0025 // Use 'Assert.Fail' instead of an always-failing assert
3636
}
3737

38+
/// <summary>
39+
/// Validates that ~, !, |, and % in assertion messages are not corrupted
40+
/// by the MSBuildLogger encoding used by the TerminalLogger.
41+
/// </summary>
42+
[TestMethod]
43+
public void FailingTestWithSpecialChars()
44+
{
45+
// These characters were corrupted by the old ~~~~, !!!!, |||| encoding.
46+
// 5 tildes, 4 bangs, 4 pipes, and percent-n which could be confused with a newline escape.
47+
#pragma warning disable MSTEST0025 // Use 'Assert.Fail' instead of an always-failing assert
48+
Assert.AreEqual("~~~~~!!!!||||%n", "not the same");
49+
#pragma warning restore MSTEST0025 // Use 'Assert.Fail' instead of an always-failing assert
50+
}
51+
3852
/// <summary>
3953
/// The skipping test.
4054
/// </summary>
Lines changed: 106 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,106 @@
1+
// Copyright (c) Microsoft Corporation. All rights reserved.
2+
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
3+
4+
using Microsoft.VisualStudio.TestPlatform.CommandLine.Internal;
5+
using Microsoft.VisualStudio.TestTools.UnitTesting;
6+
7+
namespace vstest.console.UnitTests.Internal;
8+
9+
/// <summary>
10+
/// Round-trip tests for MSBuildLogger Escape/Unescape.
11+
/// </summary>
12+
[TestClass]
13+
public class MSBuildLoggerEncoderTests
14+
{
15+
[TestMethod]
16+
public void FormatMessage_TildeCharsInMessage_SurviveRoundTrip()
17+
{
18+
var rawMessage = new string('~', 5);
19+
20+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
21+
var decoded = DecodeFirstField(encoded);
22+
23+
Assert.AreEqual(rawMessage, decoded);
24+
}
25+
26+
[TestMethod]
27+
public void FormatMessage_ExclamationCharsInMessage_SurviveRoundTrip()
28+
{
29+
var rawMessage = new string('!', 4);
30+
31+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
32+
var decoded = DecodeFirstField(encoded);
33+
34+
Assert.AreEqual(rawMessage, decoded);
35+
}
36+
37+
[TestMethod]
38+
public void FormatMessage_NewlinesInMessage_SurviveRoundTrip()
39+
{
40+
var rawMessage = "Assert failed.\r\n at MyTest()";
41+
42+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
43+
var decoded = DecodeFirstField(encoded);
44+
45+
Assert.AreEqual(rawMessage, decoded);
46+
}
47+
48+
[TestMethod]
49+
public void FormatMessage_PipesInMessage_SurviveRoundTrip()
50+
{
51+
// 4 pipes would have been eaten by the old ||||→____ replacement.
52+
var rawMessage = "expected: a]||||[b";
53+
54+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
55+
var decoded = DecodeFirstField(encoded);
56+
57+
Assert.AreEqual(rawMessage, decoded);
58+
}
59+
60+
[TestMethod]
61+
public void FormatMessage_PercentInMessage_SurviveRoundTrip()
62+
{
63+
// The escape char itself must round-trip.
64+
var rawMessage = "100% done";
65+
66+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
67+
var decoded = DecodeFirstField(encoded);
68+
69+
Assert.AreEqual(rawMessage, decoded);
70+
}
71+
72+
[TestMethod]
73+
public void FormatMessage_PercentN_NotConfusedWithNewline()
74+
{
75+
// "%n" in user data must not become a newline after round-trip.
76+
var rawMessage = "url-encoded: %n %r %p";
77+
78+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
79+
var decoded = DecodeFirstField(encoded);
80+
81+
Assert.AreEqual(rawMessage, decoded);
82+
}
83+
84+
[TestMethod]
85+
public void FormatMessage_MultipleFields_AllFieldsSurviveRoundTrip()
86+
{
87+
var rawMessage = "Assert failed.\r\n at MyTest()";
88+
var rawFile = @"C:\src\TestFile.cs";
89+
var rawLine = "42";
90+
91+
var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, rawFile, rawLine);
92+
var parts = encoded.Split(new[] { "||||" }, System.StringSplitOptions.None);
93+
// parts[0] = empty, parts[1] = name, parts[2..] = fields
94+
var decoded = new[] { MSBuildLogger.Unescape(parts[2]), MSBuildLogger.Unescape(parts[3]), MSBuildLogger.Unescape(parts[4]) };
95+
96+
Assert.AreEqual(rawMessage, decoded[0]);
97+
Assert.AreEqual(rawFile, decoded[1]);
98+
Assert.AreEqual(rawLine, decoded[2]);
99+
}
100+
101+
private static string? DecodeFirstField(string encoded)
102+
{
103+
var parts = encoded.Split(new[] { "||||" }, System.StringSplitOptions.None);
104+
return MSBuildLogger.Unescape(parts[2]);
105+
}
106+
}

0 commit comments

Comments
 (0)