diff --git a/src/Microsoft.TestPlatform.Common/Logging/InternalTestLoggerEvents.cs b/src/Microsoft.TestPlatform.Common/Logging/InternalTestLoggerEvents.cs index 256f3111a3..ef05917405 100644 --- a/src/Microsoft.TestPlatform.Common/Logging/InternalTestLoggerEvents.cs +++ b/src/Microsoft.TestPlatform.Common/Logging/InternalTestLoggerEvents.cs @@ -281,6 +281,23 @@ internal void RaiseDiscoveryComplete(DiscoveryCompleteEventArgs args) this.loggerEventQueue.Flush(); } + /// + /// Raises test run complete to the enabled loggers + /// + /// Arguments to be raised + internal void RaiseTestRunComplete(TestRunCompleteEventArgs args) + { + ValidateArg.NotNull(args, "args"); + + CheckDisposed(); + + // Size is being send as 0. (It is good to send the size as the job queue uses it) + SafeInvokeAsync(() => this.TestRunComplete, args, 0, "InternalTestLoggerEvents.SendTestRunComplete"); + + // Wait for the loggers to finish processing the messages for the run. + this.loggerEventQueue.Flush(); + } + /// /// Raise the test run complete event to test loggers and waits /// for the events to be processed. diff --git a/src/vstest.console/Internal/ConsoleLogger.cs b/src/vstest.console/Internal/ConsoleLogger.cs index 410ebe6d35..1ee98f3611 100644 --- a/src/vstest.console/Internal/ConsoleLogger.cs +++ b/src/vstest.console/Internal/ConsoleLogger.cs @@ -16,7 +16,7 @@ namespace Microsoft.VisualStudio.TestPlatform.CommandLine.Internal using Microsoft.VisualStudio.TestPlatform.ObjectModel.Logging; using Microsoft.VisualStudio.TestPlatform.Utilities; - using CommandLineResources = Microsoft.VisualStudio.TestPlatform.CommandLine.Resources.Resources; + using CommandLineResources = Resources.Resources; /// /// Logger for sending output to the console. @@ -61,7 +61,8 @@ internal enum Verbosity { Quiet, Minimal, - Normal + Normal, + Detailed } #region Fields @@ -76,11 +77,12 @@ internal enum Verbosity private Verbosity verbosityLevel = Verbosity.Minimal; #endif - private TestOutcome testOutcome = TestOutcome.None; private int testsTotal = 0; private int testsPassed = 0; private int testsFailed = 0; private int testsSkipped = 0; + private bool testRunHasErrorMessages = false; + #endregion #region Constructor @@ -168,10 +170,10 @@ public void Initialize(TestLoggerEvents events, Dictionary param var prefixExists = parameters.TryGetValue(ConsoleLogger.PrefixParam, out string prefix); if (prefixExists) { - bool.TryParse(prefix, out ConsoleLogger.AppendPrefix); + bool.TryParse(prefix, out AppendPrefix); } - this.Initialize(events, String.Empty); + Initialize(events, String.Empty); } #endregion @@ -331,17 +333,35 @@ private void TestMessageHandler(object sender, TestRunMessageEventArgs e) switch (e.Level) { case TestMessageLevel.Informational: - Output.Information(ConsoleLogger.AppendPrefix, e.Message); - break; + { + if (verbosityLevel == Verbosity.Quiet || verbosityLevel == Verbosity.Minimal) + { + break; + } + + Output.Information(AppendPrefix, e.Message); + break; + } + case TestMessageLevel.Warning: - Output.Warning(ConsoleLogger.AppendPrefix, e.Message); - break; + { + if (verbosityLevel == Verbosity.Quiet) + { + break; + } + + Output.Warning(AppendPrefix, e.Message); + break; + } + case TestMessageLevel.Error: - this.testOutcome = TestOutcome.Failed; - Output.Error(ConsoleLogger.AppendPrefix, e.Message); - break; + { + this.testRunHasErrorMessages = true; + Output.Error(AppendPrefix, e.Message); + break; + } default: - Debug.Fail("ConsoleLogger.TestMessageHandler: The test message level is unrecognized: {0}", e.Level.ToString()); + EqtTrace.Warning("ConsoleLogger.TestMessageHandler: The test message level is unrecognized: {0}", e.Level.ToString()); break; } } @@ -357,51 +377,78 @@ private void TestResultHandler(object sender, TestResultEventArgs e) // Update the test count statistics based on the result of the test. this.testsTotal++; - string name = null; - name = !string.IsNullOrEmpty(e.Result.DisplayName) ? e.Result.DisplayName : e.Result.TestCase.DisplayName; - - if (e.Result.Outcome == TestOutcome.Skipped) + string testDisplayName = e.Result.DisplayName; + if (string.IsNullOrWhiteSpace(e.Result.DisplayName)) { - this.testsSkipped++; - if (!this.verbosityLevel.Equals(Verbosity.Quiet)) - { - var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.SkippedTestIndicator, - name); - Output.Warning(false, output); - DisplayFullInformation(e.Result); - } + testDisplayName = e.Result.TestCase.DisplayName; } - else if (e.Result.Outcome == TestOutcome.Failed) - { - this.testOutcome = TestOutcome.Failed; - this.testsFailed++; - if (!this.verbosityLevel.Equals(Verbosity.Quiet)) - { - var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.FailedTestIndicator, - name); - Output.Information(false, ConsoleColor.Red, output); - DisplayFullInformation(e.Result); - } - } - else if (e.Result.Outcome == TestOutcome.Passed) - { - if (this.verbosityLevel.Equals(Verbosity.Normal)) - { - var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.PassedTestIndicator, name); - Output.Information(false, output); - DisplayFullInformation(e.Result); - } - this.testsPassed++; - } - else + + switch (e.Result.Outcome) { - if (!this.verbosityLevel.Equals(Verbosity.Quiet)) - { - var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.NotRunTestIndicator, - name); - Output.Information(false, output); - DisplayFullInformation(e.Result); - } + case TestOutcome.Skipped: + { + this.testsSkipped++; + if (this.verbosityLevel == Verbosity.Quiet) + { + break; + } + + var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.SkippedTestIndicator, testDisplayName); + Output.Warning(false, output); + if (this.verbosityLevel == Verbosity.Detailed) + { + DisplayFullInformation(e.Result); + } + + break; + } + + case TestOutcome.Failed: + { + this.testsFailed++; + if (this.verbosityLevel == Verbosity.Quiet) + { + break; + } + + var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.FailedTestIndicator, testDisplayName); + Output.Information(false, ConsoleColor.Red, output); + DisplayFullInformation(e.Result); + break; + } + + case TestOutcome.Passed: + { + this.testsPassed++; + if (this.verbosityLevel == Verbosity.Normal || this.verbosityLevel == Verbosity.Detailed) + { + var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.PassedTestIndicator, testDisplayName); + Output.Information(false, output); + if (this.verbosityLevel == Verbosity.Detailed) + { + DisplayFullInformation(e.Result); + } + } + + break; + } + + default: + { + if (this.verbosityLevel == Verbosity.Quiet) + { + break; + } + + var output = string.Format(CultureInfo.CurrentCulture, CommandLineResources.NotRunTestIndicator, testDisplayName); + Output.Information(false, output); + if (this.verbosityLevel == Verbosity.Detailed) + { + DisplayFullInformation(e.Result); + } + + break; + } } } @@ -429,17 +476,17 @@ private void TestRunCompleteHandler(object sender, TestRunCompleteEventArgs e) } // Output a summary. - if (this.testsTotal > 0) + if (testsTotal > 0) { string testCountDetails; if (e.IsAborted || e.IsCanceled) { - testCountDetails = string.Format(CultureInfo.CurrentCulture, CommandLineResources.TestRunSummaryForCanceledOrAbortedRun, testsPassed, testsFailed, testsSkipped); + testCountDetails = string.Format(CultureInfo.CurrentCulture, CommandLineResources.TestRunSummaryForCanceledOrAbortedRun, this.testsPassed, this.testsFailed, this.testsSkipped); } else { - testCountDetails = string.Format(CultureInfo.CurrentCulture, CommandLineResources.TestRunSummary, testsTotal, testsPassed, testsFailed, testsSkipped); + testCountDetails = string.Format(CultureInfo.CurrentCulture, CommandLineResources.TestRunSummary, this.testsTotal, this.testsPassed, this.testsFailed, this.testsSkipped); } Output.Information(false, testCountDetails); @@ -453,24 +500,24 @@ private void TestRunCompleteHandler(object sender, TestRunCompleteEventArgs e) { Output.Error(false, CommandLineResources.TestRunAborted); } - else if (this.testOutcome == TestOutcome.Failed && this.testsTotal > 0) + else if (this.testsFailed > 0 || this.testRunHasErrorMessages) { Output.Error(false, CommandLineResources.TestRunFailed); } - else if(this.testsTotal > 0) + else if (testsTotal > 0) { Output.Information(false, ConsoleColor.Green, CommandLineResources.TestRunSuccessful); } - if (this.testsTotal > 0) + if (testsTotal > 0) { - if (!e.ElapsedTimeInRunningTests.Equals(TimeSpan.Zero)) + if (e.ElapsedTimeInRunningTests.Equals(TimeSpan.Zero)) { - PrintTimeSpan(e.ElapsedTimeInRunningTests); + EqtTrace.Info("Skipped printing test execution time on console because it looks like the test run had faced some errors"); } else { - EqtTrace.Info("Skipped printing test execution time on console because it looks like the test run had faced some errors"); + PrintTimeSpan(e.ElapsedTimeInRunningTests); } } } @@ -491,14 +538,14 @@ public static void RaiseTestRunError(TestRunResultAggregator testRunResultAggreg // testRunResultAggregator can be null, if error is being raised in discovery context. testRunResultAggregator?.MarkTestRunFailed(); - Output.Error(ConsoleLogger.AppendPrefix, exception.Message); + Output.Error(AppendPrefix, exception.Message); // Send inner exception only when its message is different to avoid duplicate. if (exception is TestPlatformException && exception.InnerException != null && string.Compare(exception.Message, exception.InnerException.Message, StringComparison.CurrentCultureIgnoreCase) != 0) { - Output.Error(ConsoleLogger.AppendPrefix, exception.InnerException.Message); + Output.Error(AppendPrefix, exception.InnerException.Message); } } @@ -514,7 +561,7 @@ public static void RaiseTestRunWarning(TestRunResultAggregator testRunResultAggr ConsoleLogger.Output = ConsoleOutput.Instance; } - Output.Warning(ConsoleLogger.AppendPrefix, warningMessage); + Output.Warning(AppendPrefix, warningMessage); } } } diff --git a/test/vstest.console.UnitTests/Internal/ConsoleLoggerTests.cs b/test/vstest.console.UnitTests/Internal/ConsoleLoggerTests.cs index 195c526c93..bafd2020fd 100644 --- a/test/vstest.console.UnitTests/Internal/ConsoleLoggerTests.cs +++ b/test/vstest.console.UnitTests/Internal/ConsoleLoggerTests.cs @@ -126,10 +126,10 @@ public void TestMessageHandlerShouldThrowExceptionIfEventArgsIsNull() var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); loggerEvents.EnableEvents(); - Assert.ThrowsException( () => - { - loggerEvents.RaiseTestRunMessage(default(TestRunMessageEventArgs)); - }); + Assert.ThrowsException(() => + { + loggerEvents.RaiseTestRunMessage(default(TestRunMessageEventArgs)); + }); } [TestMethod] @@ -202,6 +202,159 @@ public void TestResultHandlerShouldShowStdOutMessagesBannerIfStdOutIsNotEmpty() this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Once()); } + [TestMethod] + public void NormalVerbosityShowNotStdOutMessagesForPassedTests() + { + // Setup + var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); + loggerEvents.EnableEvents(); + var parameters = new Dictionary + { + { "verbosity", "normal" } + }; + + this.consoleLogger.Initialize(loggerEvents, parameters); + var testcase = new TestCase("TestName", new Uri("some://uri"), "TestSource"); + string message = "Dummy message"; + TestResultMessage testResultMessage = new TestResultMessage(TestResultMessage.StandardOutCategory, message); + + var testresult = new ObjectModel.TestResult(testcase); + testresult.Outcome = TestOutcome.Passed; + testresult.Messages.Add(testResultMessage); + + // Raise an event on mock object + loggerEvents.RaiseTestResult(new TestResultEventArgs(testresult)); + + // Verify + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.StdOutMessagesBanner, OutputLevel.Information), Times.Never()); + this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Never()); + } + + [TestMethod] + public void DetailedVerbosityShowStdOutMessagesForPassedTests() + { + // Setup + var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); + loggerEvents.EnableEvents(); + var parameters = new Dictionary + { + { "verbosity", "detailed" } + }; + + this.consoleLogger.Initialize(loggerEvents, parameters); + var testcase = new TestCase("TestName", new Uri("some://uri"), "TestSource"); + string message = "Dummy message"; + + TestResultMessage testResultMessage = new TestResultMessage(TestResultMessage.StandardOutCategory, message); + var testresult = new ObjectModel.TestResult(testcase) + { + Outcome = TestOutcome.Passed + }; + + testresult.Messages.Add(testResultMessage); + + // Act. Raise an event on mock object + loggerEvents.RaiseTestResult(new TestResultEventArgs(testresult)); + + // Verify + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.StdOutMessagesBanner, OutputLevel.Information), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Once()); + } + + [TestMethod] + public void TestRunErrorMessageShowShouldTestRunFailed() + { + // Setup + var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); + loggerEvents.EnableEvents(); + var parameters = new Dictionary + { + { "verbosity", "detailed" } + }; + + this.consoleLogger.Initialize(loggerEvents, parameters); + string message = "Adapter Error"; + + // Act. Raise an event on mock object + loggerEvents.RaiseTestRunMessage(new TestRunMessageEventArgs(TestMessageLevel.Error, message)); + loggerEvents.RaiseTestRunComplete(new TestRunCompleteEventArgs(new Mock().Object, false, false, null, new Collection(), TimeSpan.FromSeconds(1))); + + // Verify + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.TestRunFailed, OutputLevel.Error), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(message, OutputLevel.Error), Times.Once()); + } + + [TestMethod] + public void InQuietModeTestErrorMessageShowShouldShowTestRunFailed() + { + // Setup + var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); + loggerEvents.EnableEvents(); + var parameters = new Dictionary + { + { "verbosity", "quiet" } + }; + + this.consoleLogger.Initialize(loggerEvents, parameters); + string message = "Adapter Error"; + + // Act. Raise an event on mock object + loggerEvents.RaiseTestRunMessage(new TestRunMessageEventArgs(TestMessageLevel.Error, message)); + loggerEvents.RaiseTestRunComplete(new TestRunCompleteEventArgs(new Mock().Object, false, false, null, new Collection(), TimeSpan.FromSeconds(1))); + + // Verify + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.TestRunFailed, OutputLevel.Error), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(message, OutputLevel.Error), Times.Once()); + } + + [TestMethod] + public void InQuietModeTestWarningMessageShouldNotShow() + { + // Setup + var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); + loggerEvents.EnableEvents(); + var parameters = new Dictionary + { + { "verbosity", "quiet" } + }; + + this.consoleLogger.Initialize(loggerEvents, parameters); + string message = "Adapter Warning"; + + // Act. Raise an event on mock object + loggerEvents.RaiseTestRunMessage(new TestRunMessageEventArgs(TestMessageLevel.Warning, message)); + loggerEvents.RaiseTestRunComplete(new TestRunCompleteEventArgs(new Mock().Object, false, false, null, new Collection(), TimeSpan.FromSeconds(1))); + + // Verify + this.mockOutput.Verify(o => o.WriteLine(message, OutputLevel.Warning), Times.Never()); + } + + [TestMethod] + public void InNormalModeTestWarningAndErrorMessagesShouldShow() + { + // Setup + var loggerEvents = new InternalTestLoggerEvents(TestSessionMessageLogger.Instance); + loggerEvents.EnableEvents(); + var parameters = new Dictionary + { + { "verbosity", "normal" } + }; + + this.consoleLogger.Initialize(loggerEvents, parameters); + string message = "Adapter Warning"; + string errorMessage = "Adapter Error"; + + // Act. Raise an event on mock object + loggerEvents.RaiseTestRunMessage(new TestRunMessageEventArgs(TestMessageLevel.Warning, message)); + loggerEvents.RaiseTestRunMessage(new TestRunMessageEventArgs(TestMessageLevel.Error, errorMessage)); + loggerEvents.RaiseTestRunComplete(new TestRunCompleteEventArgs(new Mock().Object, false, false, null, new Collection(), TimeSpan.FromSeconds(1))); + + // Verify + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.TestRunFailed, OutputLevel.Error), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(message, OutputLevel.Warning), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(errorMessage, OutputLevel.Error), Times.Once()); + } + [TestMethod] public void TestResultHandlerShouldNotShowStdOutMessagesBannerIfStdOutIsEmpty() { @@ -366,7 +519,7 @@ public void TestResultHandlerShouldWriteToConsoleShouldShowPassedTestsForNormalV } [TestMethod] - public void TestResultHandlerShouldShowStdOutMsgOfPassedTestIfVerbosityIsNormal() + public void TestResultHandlerShouldNotShowNotStdOutMsgOfPassedTestIfVerbosityIsNormal() { var count = 0; this.mockOutput.Setup(o => o.WriteLine(It.IsAny(), It.IsAny())).Callback( @@ -392,12 +545,12 @@ public void TestResultHandlerShouldShowStdOutMsgOfPassedTestIfVerbosityIsNormal( // Added this for synchronization SpinWait.SpinUntil(() => count == 2, 300); - this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.StdOutMessagesBanner, OutputLevel.Information), Times.Once()); - this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.StdOutMessagesBanner, OutputLevel.Information), Times.Never()); + this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Never()); } [TestMethod] - public void TestResultHandlerShouldShowDbgTrcMsg() + public void TestResultHandlerShouldNotShowDbgTrcMsg() { var count = 0; this.mockOutput.Setup(o => o.WriteLine(It.IsAny(), It.IsAny())).Callback( @@ -423,11 +576,10 @@ public void TestResultHandlerShouldShowDbgTrcMsg() // Added this for synchronization SpinWait.SpinUntil(() => count == 2, 300); - this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.DbgTrcMessagesBanner, OutputLevel.Information), Times.Once()); - this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Once()); + this.mockOutput.Verify(o => o.WriteLine(CommandLineResources.DbgTrcMessagesBanner, OutputLevel.Information), Times.Never()); + this.mockOutput.Verify(o => o.WriteLine(" " + message, OutputLevel.Information), Times.Never()); } - [TestMethod] public void TestResultHandlerShouldWriteToConsoleButSkipPassedTestsForMinimalVerbosity() { @@ -448,7 +600,7 @@ public void TestResultHandlerShouldWriteToConsoleButSkipPassedTestsForMinimalVer // Added this for synchronization SpinWait.SpinUntil(() => count == 4, 300); - + this.mockOutput.Verify(o => o.WriteLine(string.Format(CultureInfo.CurrentCulture, CommandLineResources.PassedTestIndicator, "TestName"), OutputLevel.Information), Times.Never); this.mockOutput.Verify(o => o.WriteLine(string.Format(CultureInfo.CurrentCulture, CommandLineResources.FailedTestIndicator, "TestName"), OutputLevel.Information), Times.Once()); this.mockOutput.Verify(o => o.WriteLine(string.Format(CultureInfo.CurrentCulture, CommandLineResources.SkippedTestIndicator, "TestName"), OutputLevel.Warning), Times.Once()); this.mockOutput.Verify(o => o.WriteLine(string.Format(CultureInfo.CurrentCulture, CommandLineResources.NotRunTestIndicator, "TestName"), OutputLevel.Information), Times.Exactly(2)); @@ -754,7 +906,7 @@ public void GetTestMessagesShouldWriteMessageAndStackTraceToConsole() testresults[0].Messages.Add(new TestResultMessage(TestResultMessage.StandardErrorCategory, "StandardErrorCategory")); testresults[0].Messages.Add(new TestResultMessage(TestResultMessage.AdditionalInfoCategory, "AdditionalInfoCategory")); testresults[0].Messages.Add(new TestResultMessage(TestResultMessage.AdditionalInfoCategory, "AnotherAdditionalInfoCategory")); - + foreach (var testResult in testresults) { loggerEvents.RaiseTestResult(new TestResultEventArgs(testResult));