Forward standard output of testhost (#4998)

* Capture and forward output

* Enable passing info messages from design mode client

* Add test for output

* Add project into solution

* Unignore test

playground/TestPlatform.Playground/Environment.cs

@@ -14,7 +14,6 @@ internal class EnvironmentVariables
         ["VSTEST_RUNNER_DEBUG_ATTACHVS"] = "0",
         ["VSTEST_HOST_DEBUG_ATTACHVS"] = "0",
         ["VSTEST_DATACOLLECTOR_DEBUG_ATTACHVS"] = "0",
-        ["VSTEST_EXPERIMENTAL_FORWARD_OUTPUT_FEATURE"] = "0"
     };
 
 }

src/Microsoft.TestPlatform.Client/DesignMode/DesignModeClient.cs

@@ -25,7 +25,7 @@
 using Microsoft.VisualStudio.TestPlatform.ObjectModel.Logging;
 using Microsoft.VisualStudio.TestPlatform.PlatformAbstractions;
 using Microsoft.VisualStudio.TestPlatform.PlatformAbstractions.Interfaces;
-using Microsoft.VisualStudio.TestPlatform.Utilities.Helpers.Interfaces;
+using Microsoft.VisualStudio.TestPlatform.Utilities;
 
 using CommunicationUtilitiesResources = Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.Resources.Resources;
 
@@ -43,9 +43,8 @@ public class DesignModeClient : IDesignModeClient
     private readonly ProtocolConfig _protocolConfig = Constants.DefaultProtocolConfig;
     private readonly IEnvironment _platformEnvironment;
     private readonly TestSessionMessageLogger _testSessionMessageLogger;
+    private readonly bool _forwardOutput;
     private readonly object _lockObject = new();
-    private readonly bool _isForwardingOutput;
-
     [SuppressMessage("Style", "IDE1006:Naming Styles", Justification = "Part of the public API.")]
     [SuppressMessage("Design", "CA1051:Do not declare visible instance fields", Justification = "Part of the public API")]
     protected Action<Message>? onCustomTestHostLaunchAckReceived;
@@ -57,7 +56,7 @@ public class DesignModeClient : IDesignModeClient
     /// Initializes a new instance of the <see cref="DesignModeClient"/> class.
     /// </summary>
     public DesignModeClient()
-        : this(new SocketCommunicationManager(), JsonDataSerializer.Instance, new PlatformEnvironment(), new EnvironmentVariableHelper())
+        : this(new SocketCommunicationManager(), JsonDataSerializer.Instance, new PlatformEnvironment())
     {
     }
 
@@ -73,14 +72,14 @@ public DesignModeClient()
     /// <param name="platformEnvironment">
     /// The platform Environment
     /// </param>
-    internal DesignModeClient(ICommunicationManager communicationManager, IDataSerializer dataSerializer, IEnvironment platformEnvironment, IEnvironmentVariableHelper environmentVariableHelper)
+    internal DesignModeClient(ICommunicationManager communicationManager, IDataSerializer dataSerializer, IEnvironment platformEnvironment)
     {
         _communicationManager = communicationManager;
         _dataSerializer = dataSerializer;
         _platformEnvironment = platformEnvironment;
         _testSessionMessageLogger = TestSessionMessageLogger.Instance;
+        _forwardOutput = !FeatureFlag.Instance.IsSet(FeatureFlag.VSTEST_DISABLE_STANDARD_OUTPUT_FORWARDING);
         _testSessionMessageLogger.TestRunMessage += TestRunMessageHandler;
-        _isForwardingOutput = environmentVariableHelper.GetEnvironmentVariable("VSTEST_EXPERIMENTAL_FORWARD_OUTPUT_FEATURE") == "1";
     }
 
     /// <summary>
@@ -449,8 +448,15 @@ public void TestRunMessageHandler(object? sender, TestRunMessageEventArgs e)
             case TestMessageLevel.Informational:
                 EqtTrace.Info(e.Message);
 
-                if (_isForwardingOutput || EqtTrace.IsInfoEnabled)
+                // When forwarding output we need to allow Info messages that originate from this process (or more precisely from the IMessageLogger that we
+                // are observing, but we don't have an easy way to tell apart "output" and non-output info messages. So when output forwarding is enabled
+                // we forward any informational message. This is okay, because in worst case we will send few more messages forward that are not output.
+                // And that is fine, because any adapter has access to SendMessage(MessageLevel.Informational,...) which we don't filter anywhere (it is passed
+                // as a raw message and forwarded to VS), so any adapter can spam the Tests output in VS as it wants.
+                if (_forwardOutput || EqtTrace.IsInfoEnabled)
+                {
                     SendTestMessage(e.Level, e.Message);
+                }
                 break;
 
 

src/Microsoft.TestPlatform.Common/ExtensionDecorators/ExtensionDecoratorFactory.cs

@@ -16,7 +16,7 @@ public ExtensionDecoratorFactory(IFeatureFlag featureFlag)
 
     public ITestExecutor Decorate(ITestExecutor originalTestExecutor)
     {
-        return _featureFlag.IsSet(FeatureFlag.DISABLE_SERIALTESTRUN_DECORATOR)
+        return _featureFlag.IsSet(FeatureFlag.VSTEST_DISABLE_SERIALTESTRUN_DECORATOR)
             ? originalTestExecutor
             : new SerialTestRunDecorator(originalTestExecutor);
     }

src/Microsoft.TestPlatform.CommunicationUtilities/JsonDataSerializer.cs

@@ -22,7 +22,7 @@ public class JsonDataSerializer : IDataSerializer
 {
     private static JsonDataSerializer? s_instance;
 
-    private static readonly bool DisableFastJson = FeatureFlag.Instance.IsSet(FeatureFlag.DISABLE_FASTER_JSON_SERIALIZATION);
+    private static readonly bool DisableFastJson = FeatureFlag.Instance.IsSet(FeatureFlag.VSTEST_DISABLE_FASTER_JSON_SERIALIZATION);
 
     private static readonly JsonSerializer PayloadSerializerV1; // payload serializer for version <= 1
     private static readonly JsonSerializer PayloadSerializerV2; // payload serializer for version >= 2

src/Microsoft.TestPlatform.CoreUtilities/FeatureFlag/FeatureFlag.cs

@@ -32,33 +32,42 @@ private FeatureFlag() { }
     // Only check the env variable once, when it is not set or is set to 0, consider it unset. When it is anything else, consider it set.
     public bool IsSet(string featureFlag) => _cache.GetOrAdd(featureFlag, f => (Environment.GetEnvironmentVariable(f)?.Trim() ?? "0") != "0");
 
-    private const string VSTEST_ = nameof(VSTEST_);
-
     // Added for artifact post-processing, it enable/disable the post processing.
     // Added in 17.2-preview 7.0-preview
-    public const string DISABLE_ARTIFACTS_POSTPROCESSING = VSTEST_ + nameof(DISABLE_ARTIFACTS_POSTPROCESSING);
+    public const string VSTEST_DISABLE_ARTIFACTS_POSTPROCESSING = nameof(VSTEST_DISABLE_ARTIFACTS_POSTPROCESSING);
 
     // Added for artifact post-processing, it will show old output for dotnet sdk scenario.
     // It can be useful if we need to restore old UX in case users are parsing the console output.
     // Added in 17.2-preview 7.0-preview
-    public const string DISABLE_ARTIFACTS_POSTPROCESSING_NEW_SDK_UX = VSTEST_ + nameof(DISABLE_ARTIFACTS_POSTPROCESSING_NEW_SDK_UX);
+    public const string VSTEST_DISABLE_ARTIFACTS_POSTPROCESSING_NEW_SDK_UX = nameof(VSTEST_DISABLE_ARTIFACTS_POSTPROCESSING_NEW_SDK_UX);
 
     // Faster JSON serialization relies on less internals of NewtonsoftJson, and on some additional caching.
-    public const string DISABLE_FASTER_JSON_SERIALIZATION = VSTEST_ + nameof(DISABLE_FASTER_JSON_SERIALIZATION);
+    public const string VSTEST_DISABLE_FASTER_JSON_SERIALIZATION = nameof(VSTEST_DISABLE_FASTER_JSON_SERIALIZATION);
 
     // Forces vstest.console to run all sources using the same target framework (TFM) and architecture, instead of allowing
     // multiple different tfms and architectures to run at the same time.
-    public const string DISABLE_MULTI_TFM_RUN = VSTEST_ + nameof(DISABLE_MULTI_TFM_RUN);
+    public const string VSTEST_DISABLE_MULTI_TFM_RUN = nameof(VSTEST_DISABLE_MULTI_TFM_RUN);
 
     // Disables setting a higher value for SetMinThreads. Setting SetMinThreads value to higher allows testhost to connect back faster
     // even though we are blocking additional threads because we don't have to wait for ThreadPool to start more threads.
-    public const string DISABLE_THREADPOOL_SIZE_INCREASE = VSTEST_ + nameof(DISABLE_THREADPOOL_SIZE_INCREASE);
+    public const string VSTEST_DISABLE_THREADPOOL_SIZE_INCREASE = nameof(VSTEST_DISABLE_THREADPOOL_SIZE_INCREASE);
 
     // Disable the SerialTestRunDecorator
-    public const string DISABLE_SERIALTESTRUN_DECORATOR = VSTEST_ + nameof(DISABLE_SERIALTESTRUN_DECORATOR);
+    public const string VSTEST_DISABLE_SERIALTESTRUN_DECORATOR = nameof(VSTEST_DISABLE_SERIALTESTRUN_DECORATOR);
 
     // Disable setting UTF8 encoding in console.
-    public const string DISABLE_UTF8_CONSOLE_ENCODING = VSTEST_ + nameof(DISABLE_UTF8_CONSOLE_ENCODING);
+    public const string VSTEST_DISABLE_UTF8_CONSOLE_ENCODING = nameof(VSTEST_DISABLE_UTF8_CONSOLE_ENCODING);
+
+    // VSTEST_EXPERIMENTAL_FORWARD_OUTPUT_FEATURE=1 replaced by the CAPTURING and FORWARDING flags, and was enabling
+    // the same behavior as what is now the default (both capture and forward set to TRUE).
+    // Because this is the new default we don't have to handle it in any special way. Setting it to 0 was not defined
+    // and so it also does not need any special treatment.
+    //
+    // Disable capturing standard output of testhost.
+    public const string VSTEST_DISABLE_STANDARD_OUTPUT_CAPTURING = nameof(VSTEST_DISABLE_STANDARD_OUTPUT_CAPTURING);
+
+    // Disable forwarding standard output of testhost.
+    public const string VSTEST_DISABLE_STANDARD_OUTPUT_FORWARDING = nameof(VSTEST_DISABLE_STANDARD_OUTPUT_FORWARDING);
 
     [Obsolete("Only use this in tests.")]
     internal static void Reset()

src/Microsoft.TestPlatform.CrossPlatEngine/PostProcessing/ArtifactProcessingManager.cs

@@ -81,7 +81,7 @@ public void CollectArtifacts(TestRunCompleteEventArgs testRunCompleteEventArgs,
         ValidateArg.NotNull(testRunCompleteEventArgs, nameof(testRunCompleteEventArgs));
         ValidateArg.NotNull(runSettingsXml, nameof(runSettingsXml));
 
-        if (_featureFlag.IsSet(FeatureFlag.DISABLE_ARTIFACTS_POSTPROCESSING))
+        if (_featureFlag.IsSet(FeatureFlag.VSTEST_DISABLE_ARTIFACTS_POSTPROCESSING))
         {
             EqtTrace.Verbose("ArtifactProcessingManager.CollectArtifacts: Feature disabled");
             return;
@@ -120,7 +120,7 @@ public void CollectArtifacts(TestRunCompleteEventArgs testRunCompleteEventArgs,
 
     public async Task PostProcessArtifactsAsync()
     {
-        if (_featureFlag.IsSet(FeatureFlag.DISABLE_ARTIFACTS_POSTPROCESSING))
+        if (_featureFlag.IsSet(FeatureFlag.VSTEST_DISABLE_ARTIFACTS_POSTPROCESSING))
         {
             EqtTrace.Verbose("ArtifactProcessingManager.PostProcessArtifacts: Feature disabled");
             return;

src/Microsoft.TestPlatform.ObjectModel/PublicAPI/PublicAPI.Shipped.txt

@@ -972,3 +972,5 @@ virtual Microsoft.VisualStudio.TestPlatform.ObjectModel.TestObject.ProtectedGetP
 virtual Microsoft.VisualStudio.TestPlatform.ObjectModel.TestObject.ProtectedSetPropertyValue(Microsoft.VisualStudio.TestPlatform.ObjectModel.TestProperty! property, object? value) -> void
 virtual Microsoft.VisualStudio.TestPlatform.ObjectModel.ValidateValueCallback.Invoke(object? value) -> bool
 Microsoft.VisualStudio.TestPlatform.ObjectModel.Architecture.RiscV64 = 8 -> Microsoft.VisualStudio.TestPlatform.ObjectModel.Architecture
+Microsoft.VisualStudio.TestPlatform.ObjectModel.RunConfiguration.CaptureStandardOutput.get -> bool
+Microsoft.VisualStudio.TestPlatform.ObjectModel.RunConfiguration.ForwardStandardOutput.get -> bool

src/Microsoft.TestPlatform.ObjectModel/RunSettings/RunConfiguration.cs

@@ -9,6 +9,7 @@
 using Microsoft.VisualStudio.TestPlatform.CoreUtilities;
 using Microsoft.VisualStudio.TestPlatform.ObjectModel.Utilities;
 using Microsoft.VisualStudio.TestPlatform.PlatformAbstractions;
+using Microsoft.VisualStudio.TestPlatform.Utilities;
 
 namespace Microsoft.VisualStudio.TestPlatform.ObjectModel;
 
@@ -92,6 +93,8 @@ public RunConfiguration() : base(Constants.RunConfigurationSettingsName)
         _shouldCollectSourceInformation = false;
         TargetDevice = null;
         ExecutionThreadApartmentState = Constants.DefaultExecutionThreadApartmentState;
+        CaptureStandardOutput = !FeatureFlag.Instance.IsSet(FeatureFlag.VSTEST_DISABLE_STANDARD_OUTPUT_CAPTURING);
+        ForwardStandardOutput = !FeatureFlag.Instance.IsSet(FeatureFlag.VSTEST_DISABLE_STANDARD_OUTPUT_FORWARDING);
     }
 
     /// <summary>
@@ -431,10 +434,27 @@ public bool ResultsDirectorySet
     /// </summary>
     public string? TestCaseFilter { get; private set; }
 
+    /// <summary>
     /// Path to dotnet executable to be used to invoke testhost.dll. Specifying this will skip looking up testhost.exe and will force usage of the testhost.dll.
     /// </summary>
     public string? DotnetHostPath { get; private set; }
 
+    /// <summary>
+    /// When true, we capture standard output of child processes. When false the standard output is not captured and it will end up in command line.
+    /// This makes the output visible to the user when running in vstest.console in-process. Such setup makes the behavior the same as in 17.6.3 and earlier.
+    /// 
+    /// The recommended way is to use this with ForwardStandardOutput=true to forward output as informational messages so the output is always visible in console and VS,
+    /// unless the logging level is set to Warning or higher.
+    ///
+    /// Lastly this can be used with ForwardStandardOutput=false, to suppress the output in console, which is behavior of 17.7.0 till now.
+    /// </summary>
+    public bool CaptureStandardOutput { get; private set; }
+
+    /// <summary>
+    /// Forward captured standard output of testhost as Informational test messages. Default is true. Needs CaptureStandardOutput to be true.
+    /// </summary>
+    public bool ForwardStandardOutput { get; private set; }
+
     /// <inheritdoc/>
     public override XmlElement ToXml()
     {
@@ -550,6 +570,14 @@ public override XmlElement ToXml()
             root.AppendChild(treatAsError);
         }
 
+        XmlElement captureStandardOutput = doc.CreateElement(nameof(CaptureStandardOutput));
+        captureStandardOutput.InnerXml = CaptureStandardOutput.ToString();
+        root.AppendChild(captureStandardOutput);
+
+        XmlElement forwardStandardOutput = doc.CreateElement(nameof(ForwardStandardOutput));
+        forwardStandardOutput.InnerXml = ForwardStandardOutput.ToString();
+        root.AppendChild(forwardStandardOutput);
+
         return root;
     }
 
@@ -907,6 +935,35 @@ public static RunConfiguration FromXml(XmlReader reader)
                     case "TargetFrameworkTestHostDemultiplexer":
                         reader.Skip();
                         break;
+
+                    case "CaptureStandardOutput":
+                        XmlRunSettingsUtilities.ThrowOnHasAttributes(reader);
+                        string captureStandardOutputStr = reader.ReadElementContentAsString();
+
+                        bool bCaptureStandardOutput;
+                        if (!bool.TryParse(captureStandardOutputStr, out bCaptureStandardOutput))
+                        {
+                            throw new SettingsException(string.Format(CultureInfo.CurrentCulture,
+                                Resources.Resources.InvalidSettingsIncorrectValue, Constants.RunConfigurationSettingsName, bCaptureStandardOutput, elementName));
+                        }
+
+                        runConfiguration.CaptureStandardOutput = bCaptureStandardOutput;
+                        break;
+
+                    case "ForwardStandardOutput":
+                        XmlRunSettingsUtilities.ThrowOnHasAttributes(reader);
+                        string forwardStandardOutputStr = reader.ReadElementContentAsString();
+
+                        bool bForwardStandardOutput;
+                        if (!bool.TryParse(forwardStandardOutputStr, out bForwardStandardOutput))
+                        {
+                            throw new SettingsException(string.Format(CultureInfo.CurrentCulture,
+                                Resources.Resources.InvalidSettingsIncorrectValue, Constants.RunConfigurationSettingsName, bForwardStandardOutput, elementName));
+                        }
+
+                        runConfiguration.ForwardStandardOutput = bForwardStandardOutput;
+                        break;
+
                     default:
                         // Ignore a runsettings element that we don't understand. It could occur in the case
                         // the test runner is of a newer version, but the test host is of an earlier version.

src/Microsoft.TestPlatform.ObjectModel/TestProperty/TestProperty.cs

@@ -19,7 +19,7 @@ public class TestProperty : IEquatable<TestProperty>
 {
     private static readonly ConcurrentDictionary<string, Type> TypeCache = new();
 
-    private static bool DisableFastJson { get; set; } = FeatureFlag.Instance.IsSet(FeatureFlag.DISABLE_FASTER_JSON_SERIALIZATION);
+    private static bool DisableFastJson { get; set; } = FeatureFlag.Instance.IsSet(FeatureFlag.VSTEST_DISABLE_FASTER_JSON_SERIALIZATION);
 
     private Type _valueType;
 

src/Microsoft.TestPlatform.TestHostProvider/Hosting/DefaultTestHostManager.cs

@@ -66,6 +66,7 @@ public class DefaultTestHostManager : ITestRuntimeProvider2
     private StringBuilder? _testHostProcessStdError;
     private StringBuilder? _testHostProcessStdOut;
     private IMessageLogger? _messageLogger;
+    private bool _captureOutput;
     private bool _hostExitedEventRaised;
     private TestHostManagerCallbacks? _testHostManagerCallbacks;
 
@@ -371,7 +372,9 @@ public void Initialize(IMessageLogger? logger, string runsettingsXml)
         var runConfiguration = XmlRunSettingsUtilities.GetRunConfigurationNode(runsettingsXml);
 
         _messageLogger = logger;
-        _testHostManagerCallbacks = new TestHostManagerCallbacks(_environmentVariableHelper.GetEnvironmentVariable("VSTEST_EXPERIMENTAL_FORWARD_OUTPUT_FEATURE") == "1", logger);
+        _captureOutput = runConfiguration.CaptureStandardOutput;
+        var forwardOutput = runConfiguration.ForwardStandardOutput;
+        _testHostManagerCallbacks = new TestHostManagerCallbacks(forwardOutput, logger);
         _architecture = runConfiguration.TargetPlatform;
         _targetFramework = runConfiguration.TargetFramework;
         _testHostProcess = null;
@@ -528,14 +531,15 @@ private bool LaunchHost(TestProcessStartInfo testHostStartInfo, CancellationToke
         {
             EqtTrace.Verbose("DefaultTestHostManager: Starting process '{0}' with command line '{1}'", testHostStartInfo.FileName, testHostStartInfo.Arguments);
             cancellationToken.ThrowIfCancellationRequested();
+            var outputCallback = _captureOutput ? OutputReceivedCallback : null;
             _testHostProcess = _processHelper.LaunchProcess(
                 testHostStartInfo.FileName!,
                 testHostStartInfo.Arguments,
                 testHostStartInfo.WorkingDirectory,
                 testHostStartInfo.EnvironmentVariables,
                 ErrorReceivedCallback,
                 ExitCallBack,
-                OutputReceivedCallback) as Process;
+                outputCallback) as Process;
         }
         else
         {

src/Microsoft.TestPlatform.TestHostProvider/Hosting/DotnetTestHostManager.cs

@@ -74,7 +74,7 @@ public class DotnetTestHostManager : ITestRuntimeProvider2
     private Framework? _targetFramework;
     private bool _isVersionCheckRequired = true;
     private string? _dotnetHostPath;
-
+    private bool _captureOutput;
     private protected TestHostManagerCallbacks? _testHostManagerCallbacks;
 
     /// <summary>
@@ -190,9 +190,11 @@ private set
     public void Initialize(IMessageLogger? logger, string runsettingsXml)
     {
         _hostExitedEventRaised = false;
-        _testHostManagerCallbacks = new TestHostManagerCallbacks(_environmentVariableHelper.GetEnvironmentVariable("VSTEST_EXPERIMENTAL_FORWARD_OUTPUT_FEATURE") == "1", logger);
-
         var runConfiguration = XmlRunSettingsUtilities.GetRunConfigurationNode(runsettingsXml);
+        _captureOutput = runConfiguration.CaptureStandardOutput;
+        var forwardOutput = runConfiguration.ForwardStandardOutput;
+        _testHostManagerCallbacks = new TestHostManagerCallbacks(forwardOutput, logger);
+
         _architecture = runConfiguration.TargetPlatform;
         _targetFramework = runConfiguration.TargetFramework;
         _dotnetHostPath = runConfiguration.DotnetHostPath;
@@ -738,14 +740,15 @@ private bool LaunchHost(TestProcessStartInfo testHostStartInfo, CancellationToke
 
             cancellationToken.ThrowIfCancellationRequested();
 
+            var outputCallback = _captureOutput ? OutputReceivedCallback : null;
             _testHostProcess = _processHelper.LaunchProcess(
                 testHostStartInfo.FileName!,
                 testHostStartInfo.Arguments,
                 testHostStartInfo.WorkingDirectory,
                 testHostStartInfo.EnvironmentVariables,
                 ErrorReceivedCallback,
                 ExitCallBack,
-                OutputReceivedCallback) as Process;
+                outputCallback) as Process;
         }
         else
         {