diff --git a/src/Microsoft.TestPlatform.Build/Tasks/VSTestTask2.cs b/src/Microsoft.TestPlatform.Build/Tasks/VSTestTask2.cs index c9dff0acfe..e3f32359a1 100644 --- a/src/Microsoft.TestPlatform.Build/Tasks/VSTestTask2.cs +++ b/src/Microsoft.TestPlatform.Build/Tasks/VSTestTask2.cs @@ -69,25 +69,24 @@ protected override void LogEventsFromTextOutput(string singleLine, MessageImport if (TryGetMessage(singleLine, out string name, out string?[] data)) { // See MSBuildLogger.cs for the messages produced. - // The number suffix is the amount of parameters that are sent along with the message. switch (name) { // Forward the output we receive as messages. - case "output-info1": + case "output-info": Log.LogMessage(MessageImportance.Low, data[0]); break; - case "output-warning1": + case "output-warning": Log.LogWarning(data[0]); break; - case "output-error1": + case "output-error": Log.LogError(data[0]); break; - case "run-cancel1": - case "run-abort1": + case "run-cancel": + case "run-abort": Log.LogError(data[0]); break; - case "run-finish6": + case "run-finish": // 0 - Localized summary // 1 - total tests // 2 - passed tests @@ -116,7 +115,7 @@ protected override void LogEventsFromTextOutput(string singleLine, MessageImport Log.LogMessage(MessageImportance.Low, summary); } break; - case "test-passed4": + case "test-passed": { // 0 - localized result indicator // 1 - display name @@ -128,7 +127,7 @@ protected override void LogEventsFromTextOutput(string singleLine, MessageImport var outputs = data[3]; double durationNumber = 0; - var _ = duration != null && double.TryParse(duration, out durationNumber); + _ = duration != null && double.TryParse(duration, out durationNumber); string? formattedDuration = GetFormattedDurationString(TimeSpan.FromMilliseconds(durationNumber)); var testResultWithTime = !formattedDuration.IsNullOrEmpty() ? $"{indicator} {displayName} [{formattedDuration}]" : $"{indicator} {displayName}"; @@ -156,7 +155,7 @@ protected override void LogEventsFromTextOutput(string singleLine, MessageImport } } break; - case "test-skipped2": + case "test-skipped": { // 0 - localized result indicator // 1 - display name @@ -182,63 +181,20 @@ protected override void LogEventsFromTextOutput(string singleLine, MessageImport } } break; - case "test-failed7": + case "test-failed": { - // 0 - display name - // 1 - error message - // 2 - error stack trace - // 3 - outputs - // 4 - file - // 5 - line - // 6 - place - var displayName = data[0]; // Display name - var fullErrorMessage = data[1]; - var fullStackTrace = data[2]; - var outputs = data[3]; - var file = data[4]; - var line = data[5]; - var place = data[6]; - var lineNumber = 0; - var _ = !StringUtils.IsNullOrWhiteSpace(place) && int.TryParse(line, out lineNumber); - - string? nameAndPlace = place == displayName ? place : $"{displayName}: {place}"; - string? singleLineError = JoinSingleLineAndShorten(nameAndPlace, fullErrorMessage); + // 0 - full error + // 1 - file + // 2 - line + var fullErrorMessage = data[0]; + var file = data[1]; + var line = data[2]; + _ = int.TryParse(line, out int lineNumber); file ??= string.Empty; // Report error to msbuild. - Log.LogError(null, "VSTEST1", null, file, lineNumber, 0, 0, 0, singleLineError, null); - - // Write the full error to verbose log. - // - // Log without location information, because it will give better experience in binary log viewer. By default you will see the output shortened followed by "Space: view, Ctrl+C: copy). - // Pressing space will navigate to code, instead of showing the full output. To show full output you have to right-click and select View full text. - // So we avoid providing source info - // Log.LogMessage(null, "VSTEST1", null, file, lineNumber, 0, 0, 0, MessageImportance.Low, $"{displayName}: {fullErrorMessage}{n}Stack Trace:{n}{fullStackTrace}"); - var n = Environment.NewLine; - Log.LogMessage(MessageImportance.Low, $"{displayName}: {fullErrorMessage}{n}Stack Trace:{n}{fullStackTrace}{n}Outputs:{n}{outputs}"); - } - break; - case "test-failed3": - { - // 0 - display name - // 1 - error message - // 2 - outputs - var displayName = data[0]; - var fullErrorMessage = data[1]; - var outputs = data[2]; - - var singleLineError = JoinSingleLineAndShorten(displayName, fullErrorMessage); - Log.LogError(null, "VSTEST1", null, string.Empty, 0, 0, 0, 0, singleLineError); - // Write the full error to verbose log. - // - // Log without location information, because it will give better experience in binary log viewer. By default you will see the output shortened followed by "Space: view, Ctrl+C: copy). - // Pressing space will navigate to code, instead of showing the full output. To show full output you have to right-click and select View full text. - // So we avoid providing source info - // var n = Environment.NewLine; - // Log.LogMessage(null, "VSTEST1", null, string.Empty, 0, 0, 0, 0, MessageImportance.Low, $"{displayName}: {fullErrorMessage}"); - var n = Environment.NewLine; - Log.LogMessage(MessageImportance.Low, $"{displayName}: {fullErrorMessage}{n}Outputs:{n}{outputs}"); + Log.LogError(null, "VSTEST1", null, file ?? string.Empty, lineNumber, 0, 0, 0, fullErrorMessage, null); } break; default: @@ -262,35 +218,6 @@ protected override void LogEventsFromTextOutput(string singleLine, MessageImport } } - private static string? JoinSingleLineAndShorten(string? first, string? second) - { - // Join them with space if both are not null, - // otherwise use the one that is not null. - return first != null && second != null - ? SingleLineAndShorten(first) + " " + SingleLineAndShorten(second) - : SingleLineAndShorten(first) ?? SingleLineAndShorten(second); - } - - private static string AsForwardedMessage(string?[] data) - { - return string.Join("||||", data.Select(CleanSeperator)); - } - - private static string? CleanSeperator(string? text) - { - return text == null ? null : text.Replace("||||", "___"); - } - - private static string? SingleLineAndShorten(string? text) - { - if (text == null) - { - return null; - } - - return text.Length <= 1000 ? text : text.Substring(0, 1000).Replace('\r', ' ').Replace('\n', ' '); - } - private bool TryGetMessage(string singleLine, out string name, out string?[] data) { if (singleLine.StartsWith(_messageSplitter)) diff --git a/src/vstest.console/Internal/MSBuildLogger.cs b/src/vstest.console/Internal/MSBuildLogger.cs index 214010a248..7a087592eb 100644 --- a/src/vstest.console/Internal/MSBuildLogger.cs +++ b/src/vstest.console/Internal/MSBuildLogger.cs @@ -8,6 +8,7 @@ using System.Diagnostics.CodeAnalysis; using System.Globalization; using System.Linq; +using System.Reflection; using System.Text; using System.Text.RegularExpressions; @@ -112,8 +113,13 @@ private void TestRunCompleteHandler(object? sender, TestRunCompleteEventArgs e) var failed = e.TestRunStatistics?[TestOutcome.Failed] ?? 0; var time = e.ElapsedTimeInRunningTests.TotalMilliseconds; + var resultIndicator = failed > 0 + ? CommandLineResources.FailedTestIndicator + : skipped == total + ? CommandLineResources.SkippedTestIndicator + : CommandLineResources.PassedTestIndicator; var summary = string.Format(CultureInfo.CurrentCulture, CommandLineResources.TestRunSummary, - (failed > 0 ? CommandLineResources.FailedTestIndicator : CommandLineResources.PassedTestIndicator) + "!", + resultIndicator + "!", failed, passed, skipped, @@ -121,8 +127,8 @@ private void TestRunCompleteHandler(object? sender, TestRunCompleteEventArgs e) $"[{GetFormattedDurationString(e.ElapsedTimeInRunningTests)}]" ); - SendMessage("run-finish", - summary, + + SendMessage("run-finish", summary, total.ToString(CultureInfo.InvariantCulture), passed.ToString(CultureInfo.InvariantCulture), skipped.ToString(CultureInfo.InvariantCulture), @@ -138,35 +144,48 @@ private void TestResultHandler(object? sender, TestResultEventArgs e) TPDebug.Assert(Output != null, "Initialize should have been called."); switch (e.Result.Outcome) { - case TestOutcome.Passed: - SendMessage("test-passed", - CommandLineResources.PassedTestIndicator, - e.Result.TestCase.DisplayName, - e.Result.Duration.TotalMilliseconds.ToString(CultureInfo.InvariantCulture), - FormatOutputs(e.Result)); - break; - case TestOutcome.Skipped: - SendMessage("test-skipped", - CommandLineResources.PassedTestIndicator, - e.Result.TestCase.DisplayName, - e.Result.Duration.TotalMilliseconds.ToString(CultureInfo.InvariantCulture)); - break; + // DO NOT report passed or skipped until there is a proper msbuild progress api. This is polluting user output too much. + //case TestOutcome.Passed: + // SendMessage("test-passed", + // CommandLineResources.PassedTestIndicator, + // e.Result.TestCase.DisplayName, + // e.Result.Duration.TotalMilliseconds.ToString(CultureInfo.InvariantCulture), + // FormatOutputs(e.Result)); + // break; + // DO NOT report passed or skipped until there is a proper msbuild progress api. This is polluting user output too much. + //case TestOutcome.Skipped: + // SendMessage("test-skipped", + // CommandLineResources.PassedTestIndicator, + // e.Result.TestCase.DisplayName, + // e.Result.Duration.TotalMilliseconds.ToString(CultureInfo.InvariantCulture)); + // break; case TestOutcome.Failed: var result = e.Result; Debug.WriteLine(">>>>ERR:" + result.ErrorMessage); Debug.WriteLine(">>>>STK:" + result.ErrorStackTrace); + + var formattedError = new StringBuilder(); + + formattedError.Append(result.TestCase.DisplayName); + formattedError.Append(" ("); + formattedError.Append(GetFormattedDurationString(e.Result.Duration)); + formattedError.Append("): "); + + formattedError.Append(Resources.Resources.ErrorMessageBanner); + formattedError.Append(' '); + formattedError.AppendLine(result.ErrorMessage); + + string? line = null; + string? file = null; + if (!StringUtils.IsNullOrWhiteSpace(result.ErrorStackTrace)) { - string? stackFrame = null; var stackFrames = Regex.Split(result.ErrorStackTrace, Environment.NewLine); - string? line = null; - string? file = null; - string? place = null; if (stackFrames.Length > 0) { foreach (var frame in stackFrames.Take(20)) { - if (TryGetStackFrameLocation(frame, out line, out file, out place)) + if (StackTraceHelper.TryFindLocationFromStackFrame(frame, out file, out line, out _)) { break; } @@ -182,47 +201,23 @@ private void TestResultHandler(object? sender, TestResultEventArgs e) // if there are no symbols but we collect source info, us the source info. file = result.TestCase.CodeFilePath; line = result.TestCase.LineNumber > 0 ? result.TestCase.LineNumber.ToString(CultureInfo.InvariantCulture) : null; - place = stackFrame; } else { // if there are no symbols and no source info use the dll - place = result.TestCase.DisplayName; file = result.TestCase.Source; } } - var outputs = FormatOutputs(result); - SendMessage("test-failed", result.DisplayName, result.ErrorMessage, result.ErrorStackTrace, outputs, file, line, place); - return; - } - else - { - SendMessage("test-failed", result.DisplayName, result.ErrorMessage); + formattedError.AppendLine(Resources.Resources.StacktraceBanner); + formattedError.AppendLine(result.ErrorStackTrace); } - break; - } - } - - private static bool TryGetStackFrameLocation(string stackFrame, out string? line, out string? file, out string? place) - { - // stack frame looks like this ' at Program.
$(String[] args) in S:\t\ConsoleApp81\ConsoleApp81\Program.cs:line 9' - var match = Regex.Match(stackFrame, @"^\s+at (?.+) in (?.+):line (?\d+)$?"); + AppendOutputs(result, formattedError); + SendMessage("test-failed", formattedError.ToString().TrimEnd(), file ?? string.Empty, line ?? "0"); - line = null; - file = null; - place = null; - - if (match.Success) - { - // get the exact info from stack frame. - place = match.Groups["code"].Value; - file = match.Groups["file"].Value; - line = match.Groups["line"].Value; + break; } - - return match.Success; } /// @@ -240,12 +235,12 @@ private static void SendMessage(string name, params string?[] data) var message = FormatMessage(name, data); Debug.WriteLine($"MSBUILDLOGGER: {message}"); - Output.Information(appendPrefix: false, FormatMessage(name, data)); + Output.Information(appendPrefix: false, message); } private static string FormatMessage(string name, params string?[] data) { - return $"||||{name}{data.Length}||||{string.Join("||||", data.Select(Escape))}"; + return $"||||{name}||||{string.Join("||||", data.Select(Escape))}"; } private static string? Escape(string? input) @@ -272,9 +267,8 @@ private static Collection GetTestMessages(Collection testMessageCollection, StringBuilder stringBuilder) @@ -376,3 +367,100 @@ internal static string GetFormattedDurationString(TimeSpan duration) return time.Count == 0 ? "< 1ms" : string.Join(" ", time); } } + +internal class StackTraceHelper +{ + private static Regex? s_regex; + + internal static bool TryFindLocationFromStackFrame(string? errorStackTrace, [NotNullWhen(true)] out string? file, out string? lineNumber, out string? place) + { + file = null; + place = null; + lineNumber = null; + + if (errorStackTrace == null) + { + return false; + } + + string[] stackFrames = Regex.Split(errorStackTrace, Environment.NewLine); + if (stackFrames.Length == 0) + { + return false; + } + + // Take 20 frames at max, so we don't search 1000 items in a long stack trace. + foreach (string? stackFrame in stackFrames.Take(20)) + { + if (TryGetStackFrameLocation(stackFrame, out lineNumber, out file, out place)) + { + return true; + } + } + + return false; + } + + private static bool TryGetStackFrameLocation(string stackFrame, out string? line, [NotNullWhen(true)] out string? file, out string? place) + { + InitializeRegex(); + + // stack frame looks like this ' at Program.
$(String[] args) in S:\t\ConsoleApp81\ConsoleApp81\Program.cs:line 9' + Match match = s_regex.Match(stackFrame); + + line = null; + file = null; + place = null; + + if (match.Success) + { + // get the exact info from stack frame. + place = match.Groups["code"].Value; + file = match.Groups["file"].Value; + line = match.Groups["line"].Value; + } + + return match.Success; + } + + [MemberNotNull(nameof(s_regex))] + private static void InitializeRegex() + { + if (s_regex != null) + { + return; + } + + string atResourceName = "Word_At"; + string inResourceName = "StackTrace_InFileLineNumber"; + + string? atString = null; + string? inString = null; + + // Grab words from localized resource, in case the stack trace is localized. + try + { + // Get these resources: https://github.com/dotnet/runtime/blob/main/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx + MethodInfo? getResourceStringMethod = typeof(Environment).GetMethod("GetResourceString", BindingFlags.Static | BindingFlags.NonPublic, null, [typeof(string)], null); + if (getResourceStringMethod is not null) + { + // at + atString = (string?)getResourceStringMethod.Invoke(null, [atResourceName]); + + // in {0}:line {1} + inString = (string?)getResourceStringMethod.Invoke(null, [inResourceName]); + } + } + catch + { + // If we fail, populate the defaults below. + } + + atString = atString == null || atString == atResourceName ? "at" : atString; + inString = inString == null || inString == inResourceName ? "in {0}:line {1}" : inString; + + string inPattern = string.Format(CultureInfo.InvariantCulture, inString, "(?.+)", @"(?\d+)"); + + s_regex = new Regex(@$"^ {atString} (?.+) {inPattern}$", RegexOptions.Compiled, matchTimeout: TimeSpan.FromSeconds(1)); + } +} diff --git a/test/Microsoft.TestPlatform.Acceptance.IntegrationTests/DotnetTestMSBuildOutputTests.cs b/test/Microsoft.TestPlatform.Acceptance.IntegrationTests/DotnetTestMSBuildOutputTests.cs index 0f36a9bc62..5de5f389d3 100644 --- a/test/Microsoft.TestPlatform.Acceptance.IntegrationTests/DotnetTestMSBuildOutputTests.cs +++ b/test/Microsoft.TestPlatform.Acceptance.IntegrationTests/DotnetTestMSBuildOutputTests.cs @@ -33,7 +33,9 @@ public void MSBuildLoggerCanBeEnabledByBuildPropertyAndDoesNotEatSpecialChars(Ru // C:\Users\nohwnd\AppData\Local\Temp\vstest\xvoVt\UnitTest1.cs(41): error VSTEST1: (FailingTest) SampleUnitTestProject.UnitTest1.FailingTest() Assert.AreEqual failed. Expected:<2>. Actual:<3>. [C:\Users\nohwnd\AppData\Local\Temp\vstest\xvoVt\SimpleTestProject.csproj::TargetFramework=net462] // C:\Users\nohwnd\AppData\Local\Temp\vstest\xvoVt\UnitTest1.cs(41): error VSTEST1: (FailingTest) SampleUnitTestProject.UnitTest1.FailingTest() Assert.AreEqual failed. Expected:<2>. Actual:<3>. [C:\Users\nohwnd\AppData\Local\Temp\vstest\xvoVt\SimpleTestProject.csproj::TargetFramework=netcoreapp3.1] - StdOutputContains("TerminalLoggerUnitTests.UnitTest1.FailingTest() Assert.AreEqual failed. Expected:<ğğğ𦮙我們剛才從𓋴𓅓𓏏𓇏𓇌𓀀 (System.String)>. Actual:<3 (System.Int32)>."); + StdOutputContains("error VSTEST1: FailingTest ("); + StdOutputContains("): Error Message: Assert.AreEqual failed. Expected:<ğğğ𦮙我們剛才從𓋴𓅓𓏏𓇏𓇌𓀀 (System.String)>. Actual:<3 (System.Int32)>."); + StdOutputContains("at TerminalLoggerUnitTests.UnitTest1.FailingTest() in"); // 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"); diff --git a/test/Microsoft.TestPlatform.TestUtilities/IntegrationTestBase.cs b/test/Microsoft.TestPlatform.TestUtilities/IntegrationTestBase.cs index 2b41b5496c..f8f546ce83 100644 --- a/test/Microsoft.TestPlatform.TestUtilities/IntegrationTestBase.cs +++ b/test/Microsoft.TestPlatform.TestUtilities/IntegrationTestBase.cs @@ -428,12 +428,12 @@ public void StdErrorDoesNotContains(string substring) public void StdOutputContains(string substring) { - Assert.IsTrue(_standardTestOutput.Contains(substring), $"StdOutput:{Environment.NewLine} Expected substring: {substring}{Environment.NewLine}Actual string: {_standardTestOutput}"); + Assert.IsTrue(_standardTestOutput.Contains(substring), $"{Environment.NewLine}StdOutput:{Environment.NewLine}{Environment.NewLine}Expected substring: {substring}{Environment.NewLine}{Environment.NewLine}Actual string: {_standardTestOutput}"); } public void StdOutputDoesNotContains(string substring) { - Assert.IsFalse(_standardTestOutput.Contains(substring), $"StdOutput:{Environment.NewLine} Not expected substring: {substring}{Environment.NewLine}Actual string: {_standardTestOutput}"); + Assert.IsFalse(_standardTestOutput.Contains(substring), $"{Environment.NewLine}StdOutput:{Environment.NewLine}{Environment.NewLine}Not expected substring: {substring}{Environment.NewLine}{Environment.NewLine}Actual string: {_standardTestOutput}"); } public void ExitCodeEquals(int exitCode)