Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
37 changes: 36 additions & 1 deletion src/Microsoft.TestPlatform.Build/Tasks/VSTestTask2.cs
Original file line number Diff line number Diff line change
Expand Up @@ -265,7 +265,7 @@ private bool TryGetMessage(string singleLine, out string name, out string?[] dat
{
var parts = singleLine.Split(_messageSplitterArray, StringSplitOptions.None);
name = parts[1];
data = parts.Skip(2).Take(parts.Length).Select(p => p?.Replace("~~~~", "\r").Replace("!!!!", "\n")).ToArray();
data = parts.Skip(2).Take(parts.Length).Select(Unescape).ToArray();
return true;
}

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

/// <summary>
/// Reverses MSBuildLogger.Escape. Single-pass scanner to correctly handle
/// sequences like <c>%%n</c> (literal <c>%n</c>, not <c>%</c> + newline).
/// </summary>
private static string? Unescape(string? input)
{
if (input == null)
{
return null;
}

var sb = new StringBuilder(input.Length);
for (int i = 0; i < input.Length; i++)
{
if (input[i] == '%' && i + 1 < input.Length)
{
char next = input[++i];
switch (next)
{
case '%': sb.Append('%'); break;
case 'p': sb.Append('|'); break;
case 'r': sb.Append('\r'); break;
case 'n': sb.Append('\n'); break;
default: sb.Append('%'); sb.Append(next); break;
}
}
else
{
sb.Append(input[i]);
}
}
Comment thread
nohwnd marked this conversation as resolved.

return sb.ToString();
}

protected override string? GenerateCommandLineCommands()
{
return TestTaskUtils.CreateCommandLineArguments(this);
Expand Down
57 changes: 48 additions & 9 deletions src/vstest.console/Internal/MSBuildLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -229,11 +229,12 @@ private void TestResultHandler(object? sender, TestResultEventArgs e)
}

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

private static string FormatMessage(string name, params string?[] data)
internal static string FormatMessage(string name, params string?[] data)
{
return $"||||{name}||||{string.Join("||||", data.Select(Escape))}";
}
Expand All @@ -258,11 +259,49 @@ private static string FormatMessage(string name, params string?[] data)
return null;
}

// '%'-based escaping: escape the escape char first, then special chars.
// This is lossless (unlike the old ||||→____ replacement) and stays readable
// in MSBuild binary logs (unlike \x02/\x03 control chars).
return input
// Cleanup characters that we are using ourselves to delimit the message
.Replace("||||", "____").Replace("~~~~", "____").Replace("!!!!", "____")
// Replace new line characters that would change how the message is consumed.
.Replace("\r", "~~~~").Replace("\n", "!!!!");
.Replace("%", "%%")
.Replace("|", "%p")
.Replace("\r", "%r")
.Replace("\n", "%n");
}

/// <summary>
/// Reverses <see cref="Escape"/>. Must be a single-pass scanner — chained Replace
/// would incorrectly decode <c>%%n</c> as <c>%\n</c> instead of <c>%n</c>.
/// </summary>
internal static string? Unescape(string? input)
{
if (input == null)
{
return null;
}

var sb = new StringBuilder(input.Length);
for (int i = 0; i < input.Length; i++)
{
if (input[i] == '%' && i + 1 < input.Length)
{
char next = input[++i];
switch (next)
{
case '%': sb.Append('%'); break;
case 'p': sb.Append('|'); break;
case 'r': sb.Append('\r'); break;
case 'n': sb.Append('\n'); break;
default: sb.Append('%'); sb.Append(next); break;
}
}
else
{
sb.Append(input[i]);
}
}
Comment thread
nohwnd marked this conversation as resolved.

return sb.ToString();
}

/// <summary>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,14 @@ public void MSBuildLoggerCanBeEnabledByBuildPropertyAndDoesNotEatSpecialChars(Ru
StdOutputContains("FailingTest (");
StdOutputContains("Expected: \"ğğğ𦮙我們剛才從𓋴𓅓𓏏𓇏𓇌𓀀\"");
StdOutputContains("at TerminalLoggerUnitTests.UnitTest1.FailingTest() in");

// Verify that ~, !, |, and % characters in test output survive the MSBuildLogger encoding round-trip.
StdOutputContains("FailingTestWithSpecialChars (");
StdOutputContains("~~~~~");
StdOutputContains("!!!!");
StdOutputContains("||||");
StdOutputContains("%n");

// We are sending those as low prio messages, they won't show up on screen but will be in binlog.
//StdOutputContains("passed PassingTest");
//StdOutputContains("skipped SkippingTest");
Expand All @@ -57,7 +65,7 @@ public void MSBuildLoggerCanBeDisabledByBuildProperty(RunnerInfo runnerInfo)
InvokeDotnetTest($@"{projectPath} -nodereuse:false /p:VsTestUseMSBuildOutput=false /p:PackageVersion={IntegrationTestEnvironment.LatestLocallyBuiltNugetVersion}", workingDirectory: Path.GetDirectoryName(projectPath));

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

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

ExitCodeEquals(1);
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -175,6 +175,76 @@ public void LogEventsFromTextOutput_NullOutput_ShouldNotThrow()
task.TestLogEventsFromTextOutput("||||output-info||||", MessageImportance.High);
}

[TestMethod]
public void LogEventsFromTextOutput_TestFailed_TildeCharsInMessage_ShouldNotBeCorrupted()
{
var task = CreateVSTestTask2();
var engine = (RecordingBuildEngine)task.BuildEngine;

// 5 tilde chars — the old encoding replaced ~~~~ (4 tildes) with ____
var tildeString = new string('~', 5);
task.TestLogEventsFromTextOutput($"||||test-failed||||{tildeString}||||TestFile.cs||||42", MessageImportance.High);

Assert.HasCount(1, engine.Errors);
Assert.Contains(tildeString, engine.Errors[0].Message ?? string.Empty);
}

[TestMethod]
public void LogEventsFromTextOutput_TestFailed_ExclamationCharsInMessage_ShouldNotBeCorrupted()
{
var task = CreateVSTestTask2();
var engine = (RecordingBuildEngine)task.BuildEngine;

// 4 exclamation marks — the old encoding replaced !!!! (4 bangs) with ____
var bangString = new string('!', 4);
task.TestLogEventsFromTextOutput($"||||test-failed||||{bangString}||||TestFile.cs||||42", MessageImportance.High);

Assert.HasCount(1, engine.Errors);
Assert.Contains(bangString, engine.Errors[0].Message ?? string.Empty);
}

[TestMethod]
public void LogEventsFromTextOutput_TestFailed_NewlinesEncodedWithPercentEscapes_ShouldBeRestored()
{
var task = CreateVSTestTask2();
var engine = (RecordingBuildEngine)task.BuildEngine;

// Simulate what MSBuildLogger.Escape produces: \r → %r, \n → %n
var messageWithNewlines = "Assert failed%r%n at MyTest()";
task.TestLogEventsFromTextOutput($"||||test-failed||||{messageWithNewlines}||||TestFile.cs||||42", MessageImportance.High);

Assert.HasCount(1, engine.Errors);
Assert.Contains("Assert failed\r\n at MyTest()", engine.Errors[0].Message ?? string.Empty);
}

[TestMethod]
public void LogEventsFromTextOutput_TestFailed_PipesInMessage_ShouldNotBreakParsing()
{
var task = CreateVSTestTask2();
var engine = (RecordingBuildEngine)task.BuildEngine;

// Pipes are escaped as %p by MSBuildLogger.Escape, so they can't break the |||| delimiter.
var messageWithPipes = "expected: a]%p%p%p%p[b";
task.TestLogEventsFromTextOutput($"||||test-failed||||{messageWithPipes}||||TestFile.cs||||42", MessageImportance.High);

Assert.HasCount(1, engine.Errors);
Assert.Contains("expected: a]||||[b", engine.Errors[0].Message ?? string.Empty);
}

[TestMethod]
public void LogEventsFromTextOutput_TestFailed_PercentInMessage_ShouldNotBeCorrupted()
{
var task = CreateVSTestTask2();
var engine = (RecordingBuildEngine)task.BuildEngine;

// %% is the escape for literal %, and %%n must decode to %n not to %+newline.
var messageWithPercent = "100%%%% done %%n not a newline";
task.TestLogEventsFromTextOutput($"||||test-failed||||{messageWithPercent}||||TestFile.cs||||42", MessageImportance.High);

Assert.HasCount(1, engine.Errors);
Assert.Contains("100%% done %n not a newline", engine.Errors[0].Message ?? string.Empty);
}

private static TestableVSTestTask2 CreateVSTestTask2()
{
Comment thread
nohwnd marked this conversation as resolved.
var engine = new RecordingBuildEngine();
Expand Down
14 changes: 14 additions & 0 deletions test/TestAssets/TerminalLoggerTestProject/UnitTest1.cs
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,20 @@ public void FailingTest()
#pragma warning restore MSTEST0025 // Use 'Assert.Fail' instead of an always-failing assert
}

/// <summary>
/// Validates that ~, !, |, and % in assertion messages are not corrupted
/// by the MSBuildLogger encoding used by the TerminalLogger.
/// </summary>
[TestMethod]
public void FailingTestWithSpecialChars()
{
// These characters were corrupted by the old ~~~~, !!!!, |||| encoding.
// 5 tildes, 4 bangs, 4 pipes, and percent-n which could be confused with a newline escape.
#pragma warning disable MSTEST0025 // Use 'Assert.Fail' instead of an always-failing assert
Assert.AreEqual("~~~~~!!!!||||%n", "not the same");
#pragma warning restore MSTEST0025 // Use 'Assert.Fail' instead of an always-failing assert
}

/// <summary>
/// The skipping test.
/// </summary>
Expand Down
106 changes: 106 additions & 0 deletions test/vstest.console.UnitTests/Internal/MSBuildLoggerEncoderTests.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,106 @@
// Copyright (c) Microsoft Corporation. All rights reserved.
// Licensed under the MIT license. See LICENSE file in the project root for full license information.

using Microsoft.VisualStudio.TestPlatform.CommandLine.Internal;
using Microsoft.VisualStudio.TestTools.UnitTesting;

namespace vstest.console.UnitTests.Internal;

/// <summary>
/// Round-trip tests for MSBuildLogger Escape/Unescape.
/// </summary>
[TestClass]
public class MSBuildLoggerEncoderTests
{
[TestMethod]
public void FormatMessage_TildeCharsInMessage_SurviveRoundTrip()
{
var rawMessage = new string('~', 5);

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
var decoded = DecodeFirstField(encoded);

Assert.AreEqual(rawMessage, decoded);
}

[TestMethod]
public void FormatMessage_ExclamationCharsInMessage_SurviveRoundTrip()
{
var rawMessage = new string('!', 4);

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
var decoded = DecodeFirstField(encoded);

Assert.AreEqual(rawMessage, decoded);
}

[TestMethod]
public void FormatMessage_NewlinesInMessage_SurviveRoundTrip()
{
var rawMessage = "Assert failed.\r\n at MyTest()";

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
var decoded = DecodeFirstField(encoded);

Assert.AreEqual(rawMessage, decoded);
}

[TestMethod]
public void FormatMessage_PipesInMessage_SurviveRoundTrip()
{
// 4 pipes would have been eaten by the old ||||→____ replacement.
var rawMessage = "expected: a]||||[b";

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
var decoded = DecodeFirstField(encoded);

Assert.AreEqual(rawMessage, decoded);
}

[TestMethod]
public void FormatMessage_PercentInMessage_SurviveRoundTrip()
{
// The escape char itself must round-trip.
var rawMessage = "100% done";

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
var decoded = DecodeFirstField(encoded);

Assert.AreEqual(rawMessage, decoded);
}

[TestMethod]
public void FormatMessage_PercentN_NotConfusedWithNewline()
{
// "%n" in user data must not become a newline after round-trip.
var rawMessage = "url-encoded: %n %r %p";

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, "TestFile.cs", "42");
var decoded = DecodeFirstField(encoded);

Assert.AreEqual(rawMessage, decoded);
}

[TestMethod]
public void FormatMessage_MultipleFields_AllFieldsSurviveRoundTrip()
{
var rawMessage = "Assert failed.\r\n at MyTest()";
var rawFile = @"C:\src\TestFile.cs";
var rawLine = "42";

var encoded = MSBuildLogger.FormatMessage("test-failed", rawMessage, rawFile, rawLine);
var parts = encoded.Split(new[] { "||||" }, System.StringSplitOptions.None);
// parts[0] = empty, parts[1] = name, parts[2..] = fields
var decoded = new[] { MSBuildLogger.Unescape(parts[2]), MSBuildLogger.Unescape(parts[3]), MSBuildLogger.Unescape(parts[4]) };

Assert.AreEqual(rawMessage, decoded[0]);
Assert.AreEqual(rawFile, decoded[1]);
Assert.AreEqual(rawLine, decoded[2]);
}

private static string? DecodeFirstField(string encoded)
{
var parts = encoded.Split(new[] { "||||" }, System.StringSplitOptions.None);
return MSBuildLogger.Unescape(parts[2]);
}
}
Loading