Merge pull request #23 from spekt/AddStdOut

Feat: Support logging system-out and error-out

README.md

@@ -86,7 +86,7 @@ This option alters the testcase name attribute. By default, this contains only t
 
 #### FailureBodyFormat
 
-When set to default, the body will contain only the exception which is captured by vstest. Verbose will prepend the body with 'Expected X, Actual Y' similar to how it is displayed in the standard test output. 'Expected X, Actual Y' are normally only contained in the failure message. See [here](/docs/gitlab-recommendation.md) for an example of why this might be useful.
+When set to default, the body will contain only the exception which is captured by vstest. Verbose will prepend the body with 'Expected X, Actual Y' similar to how it is displayed in the standard test output. 'Expected X, Actual Y' are normally only contained in the failure message. Additionally, Verbose will include standard output from the test in the failure message. See [here](/docs/gitlab-recommendation.md) for an example of why this might be useful.
 
 ##### Allowed Values
 

docs/gitlab-recommendation.md

@@ -42,4 +42,4 @@ Test:
 
 ## Notes
 
-Screen shots and behavior are current as of GitLab Community Edition 11.11.8. 
+Screen shots and behavior are current as of GitLab Enterprise Edition 13.0.0-pre.

src/JUnit.Xml.TestLogger/JUnitXmlTestLogger.cs

@@ -9,7 +9,6 @@ namespace Microsoft.VisualStudio.TestPlatform.Extension.JUnit.Xml.TestLogger
     using System.IO;
     using System.Linq;
     using System.Text;
-    using System.Text.RegularExpressions;
     using System.Xml;
     using System.Xml.Linq;
     using Microsoft.VisualStudio.TestPlatform.ObjectModel;
@@ -48,6 +47,16 @@ public class JUnitXmlTestLogger : ITestLoggerWithParameters
         private readonly object resultsGuard = new object();
         private string outputFilePath;
 
+        /// <summary>
+        /// Recieves information messages, along with StdOut from test methods.
+        /// </summary>
+        private StringBuilder stdOut = new StringBuilder();
+
+        /// <summary>
+        /// Recieves both warning and error messages.
+        /// </summary>
+        private StringBuilder stdErr = new StringBuilder();
+
         private List<TestResultInfo> results;
         private DateTime utcStartTime;
 
@@ -130,7 +139,9 @@ public static IEnumerable<TestSuite> GroupTestSuites(IEnumerable<TestSuite> suit
         /// Initialized called by dotnet test.
         /// </summary>
         /// <param name="events">Test logger event.</param>
-        /// <param name="testResultsDirPath">A single string is assumed to be the test result directory argument.</param>
+        /// <param name="testResultsDirPath">
+        /// A single string is assumed to be the test result directory argument.
+        /// </param>
         public void Initialize(TestLoggerEvents events, string testResultsDirPath)
         {
             if (events == null)
@@ -151,7 +162,9 @@ public void Initialize(TestLoggerEvents events, string testResultsDirPath)
         /// Initialized called by dotnet test.
         /// </summary>
         /// <param name="events">Test logger event.</param>
-        /// <param name="parameters">Dictionary of key value pairs provided by the user, semicolon delimited (i.e. 'key1=val1;key2=val2').</param>
+        /// <param name="parameters">
+        /// Dictionary of key value pairs provided by the user, semicolon delimited (i.e. 'key1=val1;key2=val2').
+        /// </param>
         public void Initialize(TestLoggerEvents events, Dictionary<string, string> parameters)
         {
             if (events == null)
@@ -241,10 +254,19 @@ public void Initialize(TestLoggerEvents events, Dictionary<string, string> param
         }
 
         /// <summary>
-        /// Called when a test message is received.
+        /// Called when a test message is received. These messages are coming from the test
+        /// framework, and don't contain standard output produced by test code.
         /// </summary>
         internal void TestMessageHandler(object sender, TestRunMessageEventArgs e)
         {
+            if (e.Level == TestMessageLevel.Informational)
+            {
+                this.stdOut.AppendLine(e.Message);
+            }
+            else
+            {
+                this.stdErr.AppendLine(e.Message);
+            }
         }
 
         /// <summary>
@@ -277,8 +299,14 @@ internal void TestResultHandler(object sender, TestResultEventArgs e)
         {
             TestResult result = e.Result;
 
-            var parsedName = TestCaseNameParser.Parse(result.TestCase.FullyQualifiedName);
+            if (e.Result.Messages.Count > 0)
+            {
+                this.stdOut.AppendLine();
+                this.stdOut.AppendLine(result.TestCase.FullyQualifiedName);
+                this.stdOut.AppendLine(Indent(result.Messages));
+            }
 
+            var parsedName = TestCaseNameParser.Parse(result.TestCase.FullyQualifiedName);
             lock (this.resultsGuard)
             {
                 this.results.Add(new TestResultInfo(
@@ -395,6 +423,27 @@ private static TestSuite AggregateTestSuites(
             };
         }
 
+        /// <summary>
+        /// Produces a consistently indented output, taking into account that incoming messages
+        /// often have new lines within a message.
+        /// </summary>
+        private static string Indent(IReadOnlyCollection<TestResultMessage> messages)
+        {
+            var indent = "    ";
+
+            // Splitting on any line feed or carrage return because a message may include new lines
+            // that are inconsistent with the Environment.NewLine. We then remove all blank lines so
+            // it shouldn't cause an issue that this generates extra line breaks.
+            return
+                indent +
+                string.Join(
+                    $"{Environment.NewLine}{indent}",
+                    messages.SelectMany(m =>
+                        m.Text.Split(new string[] { "\r", "\n" }, StringSplitOptions.None)
+                              .Where(x => !string.IsNullOrWhiteSpace(x))
+                              .Select(x => x.Trim())));
+        }
+
         private void InitializeImpl(TestLoggerEvents events, string outputPath)
         {
             events.TestRunMessage += this.TestMessageHandler;
@@ -428,13 +477,14 @@ private XElement CreateTestSuiteElement(List<TestResultInfo> results)
             var testCaseElements = results.Select(a => this.CreateTestCaseElement(a));
 
             // Adding required properties, system-out, and system-err elements in the correct
-            // positions as required by the xsd.
+            // positions as required by the xsd. In system-out collapse consequtive newlines to a
+            // single newline.
             var element = new XElement(
                 "testsuite",
                 new XElement("properties"),
                 testCaseElements,
-                new XElement("system-out", "Junit Logger does not log standard output"),
-                new XElement("system-err", "Junit Logger does not log error output"));
+                new XElement("system-out", this.stdOut.ToString()),
+                new XElement("system-err", this.stdErr.ToString()));
 
             element.SetAttributeValue("name", Path.GetFileName(results.First().AssemblyPath));
 
@@ -472,9 +522,8 @@ private XElement CreateTestCaseElement(TestResultInfo result)
                 testcaseElement.SetAttributeValue("name", result.Name);
             }
 
-            // Ensure time value is never zero because gitlab treats 0 like its null.
-            // 0.1 micro seconds should be low enough it won't interfere with anyone
-            // monitoring test duration.
+            // Ensure time value is never zero because gitlab treats 0 like its null. 0.1 micro
+            // seconds should be low enough it won't interfere with anyone monitoring test duration.
             testcaseElement.SetAttributeValue(
                 "time",
                 Math.Max(0.0000001f, result.Duration.TotalSeconds).ToString("0.0000000"));
@@ -487,12 +536,20 @@ private XElement CreateTestCaseElement(TestResultInfo result)
                 {
                     failureBodySB.AppendLine(result.ErrorMessage);
 
-                    // Stack trace included to mimic the normal test output
+                    // Stack trace label included to mimic the normal test output
                     failureBodySB.AppendLine("Stack Trace:");
                 }
 
                 failureBodySB.AppendLine(result.ErrorStackTrace);
 
+                if (this.FailureBodyFormatOption == FailureBodyFormat.Verbose &&
+                    result.Messages.Count > 0)
+                {
+                    failureBodySB.AppendLine("Standard Output:");
+
+                    failureBodySB.AppendLine(Indent(result.Messages));
+                }
+
                 var failureElement = new XElement("failure", failureBodySB.ToString().Trim());
 
                 failureElement.SetAttributeValue("type", "failure"); // TODO are there failure types?

test/JUnit.Xml.TestLogger.AcceptanceTests/JUnitTestLoggerAcceptanceTests.cs

@@ -95,6 +95,26 @@ public void TestResultFileShouldContainTestCases()
             Assert.AreEqual(6, skips.Count());
         }
 
+        [TestMethod]
+        public void TestResultFileShouldContainStandardOut()
+        {
+            var node = this.resultsXml.XPathSelectElement("/testsuites/testsuite/system-out");
+
+            Assert.IsTrue(node.Value.Contains("{2010CAE3-7BC0-4841-A5A3-7D5F947BB9FB}"));
+            Assert.IsTrue(node.Value.Contains("{998AC9EC-7429-42CD-AD55-72037E7AF3D8}"));
+            Assert.IsTrue(node.Value.Contains("{EEEE1DA6-6296-4486-BDA5-A50A19672F0F}"));
+            Assert.IsTrue(node.Value.Contains("{C33FF4B5-75E1-4882-B968-DF9608BFE7C2}"));
+        }
+
+        [TestMethod]
+        public void TestResultFileShouldContainErrordOut()
+        {
+            var node = this.resultsXml.XPathSelectElement("/testsuites/testsuite/system-err");
+
+            Assert.IsTrue(node.Value.Contains("{D46DFA10-EEDD-49E5-804D-FE43051331A7}"));
+            Assert.IsTrue(node.Value.Contains("{33F5FD22-6F40-499D-98E4-481D87FAEAA1}"));
+        }
+
         [TestMethod]
         public void LoggedXmlValidatesAgainstXsdSchema()
         {

test/JUnit.Xml.TestLogger.AcceptanceTests/JUnitTestLoggerFormatOptionsAcceptanceTests.cs

@@ -15,8 +15,9 @@ namespace JUnit.Xml.TestLogger.AcceptanceTests
     /// Acceptance tests evaluate the most recent output of the build.ps1 script, NOT the most
     /// recent build performed by visual studio or dotnet.build
     ///
-    /// These acceptance tests look at the specific places output is expected to change because of the format option specified.
-    /// Accordingly, these tests cannot protect against other changes occurring due to the formatting option.
+    /// These acceptance tests look at the specific places output is expected to change because of
+    /// the format option specified. Accordingly, these tests cannot protect against other changes
+    /// occurring due to the formatting option.
     /// </summary>
     [TestClass]
     public class JUnitTestLoggerFormatOptionsAcceptanceTests
@@ -35,14 +36,31 @@ public void FailureBodyFormat_Default_ShouldntStartWithMessage()
 
             foreach (var failure in failures)
             {
-                // Strip new line and carrige return. These may be inconsistent depending on environment settings
+                // Strip new line and carrige return. These may be inconsistent depending on
+                // environment settings
                 var message = failure.Attribute("message").Value.Replace("\r", string.Empty).Replace("\n", string.Empty);
                 var body = failure.Value.Replace("\r", string.Empty).Replace("\n", string.Empty);
 
                 Assert.IsFalse(body.StartsWith(message));
             }
         }
 
+        [TestMethod]
+        public void FailureBodyFormat_Verbose_ShouldNotContainConsoleOut()
+        {
+            DotnetTestFixture.Execute("failure-verbose-test-results.xml;FailureBodyFormat=Default");
+            string resultsFile = Path.Combine(DotnetTestFixture.RootDirectory, "failure-verbose-test-results.xml");
+            XDocument resultsXml = XDocument.Load(resultsFile);
+
+            var failures = resultsXml.XPathSelectElements("/testsuites/testsuite")
+                .Descendants()
+                .Where(x => x.Name.LocalName == "failure")
+                .ToList();
+
+            Assert.AreEqual(0, failures.Count(x => x.Value.Contains("{EEEE1DA6-6296-4486-BDA5-A50A19672F0F}")));
+            Assert.AreEqual(0, failures.Count(x => x.Value.Contains("{C33FF4B5-75E1-4882-B968-DF9608BFE7C2}")));
+        }
+
         [TestMethod]
         public void FailureBodyFormat_Verbose_ShouldStartWithMessage()
         {
@@ -57,14 +75,31 @@ public void FailureBodyFormat_Verbose_ShouldStartWithMessage()
 
             foreach (var failure in failures)
             {
-                // Strip new line and carrige return. These may be inconsistent depending on environment settings
+                // Strip new line and carrige return. These may be inconsistent depending on
+                // environment settings
                 var message = failure.Attribute("message").Value.Replace("\r", string.Empty).Replace("\n", string.Empty);
                 var body = failure.Value.Replace("\r", string.Empty).Replace("\n", string.Empty);
 
                 Assert.IsTrue(body.Trim().StartsWith(message.Trim()));
             }
         }
 
+        [TestMethod]
+        public void FailureBodyFormat_Verbose_ShouldContainConsoleOut()
+        {
+            DotnetTestFixture.Execute("failure-verbose-test-results.xml;FailureBodyFormat=Verbose");
+            string resultsFile = Path.Combine(DotnetTestFixture.RootDirectory, "failure-verbose-test-results.xml");
+            XDocument resultsXml = XDocument.Load(resultsFile);
+
+            var failures = resultsXml.XPathSelectElements("/testsuites/testsuite")
+                .Descendants()
+                .Where(x => x.Name.LocalName == "failure")
+                .ToList();
+
+            Assert.AreEqual(1, failures.Count(x => x.Value.Contains("{EEEE1DA6-6296-4486-BDA5-A50A19672F0F}")));
+            Assert.AreEqual(1, failures.Count(x => x.Value.Contains("{C33FF4B5-75E1-4882-B968-DF9608BFE7C2}")));
+        }
+
         [TestMethod]
         public void MethodFormat_Default_ShouldBeOnlyTheMethod()
         {
@@ -102,8 +137,8 @@ public void MethodFormat_Class_ShouldIncludeClass()
             {
                 var parsedName = TestCaseNameParser.Parse(testcase.Attribute("name").Value);
 
-                // If the name is parsable into two pieces, then we have a two piece name
-                // and consider that to be a passing result.
+                // If the name is parsable into two pieces, then we have a two piece name and
+                // consider that to be a passing result.
                 Assert.AreNotEqual(parsedName.TypeName, TestCaseNameParser.TestCaseParserUnknownType);
             }
         }

test/assets/JUnit.Xml.TestLogger.NetCore.Tests/UnitTest1.cs

@@ -11,12 +11,19 @@ public class UnitTest1
         [Description("Passing test description")]
         public async Task PassTest11()
         {
+            Console.WriteLine("{2010CAE3-7BC0-4841-A5A3-7D5F947BB9FB}");
+            Console.WriteLine("{998AC9EC-7429-42CD-AD55-72037E7AF3D8}");
             await Task.Delay(TimeSpan.FromMilliseconds(400));
         }
 
         [Test]
         public void FailTest11()
         {
+            Console.WriteLine("{EEEE1DA6-6296-4486-BDA5-A50A19672F0F}");
+            Console.WriteLine("{C33FF4B5-75E1-4882-B968-DF9608BFE7C2}");
+            Console.Error.WriteLine("{D46DFA10-EEDD-49E5-804D-FE43051331A7}");
+            Console.Error.WriteLine("{33F5FD22-6F40-499D-98E4-481D87FAEAA1}");
+
             Assert.False(true);
         }