diff --git a/test/TestAssets/TestProjects/TestProjectWithLiveOutput/Program.cs b/test/TestAssets/TestProjects/TestProjectWithLiveOutput/Program.cs new file mode 100644 index 000000000000..dd015928be53 --- /dev/null +++ b/test/TestAssets/TestProjects/TestProjectWithLiveOutput/Program.cs @@ -0,0 +1,94 @@ +using Microsoft.Testing.Platform.Builder; +using Microsoft.Testing.Platform.Capabilities.TestFramework; +using Microsoft.Testing.Platform.Extensions.Messages; +using Microsoft.Testing.Platform.Extensions.OutputDevice; +using Microsoft.Testing.Platform.Extensions.TestFramework; +using Microsoft.Testing.Platform.OutputDevice; +using Microsoft.Testing.Platform.Services; + +var testApplicationBuilder = await TestApplication.CreateBuilderAsync(args); + +testApplicationBuilder.RegisterTestFramework(_ => new TestFrameworkCapabilities(), (_, serviceProvider) => new DummyTestAdapter(serviceProvider.GetOutputDevice())); + +using var testApplication = await testApplicationBuilder.BuildAsync(); +return await testApplication.RunAsync(); + +public class DummyTestAdapter(IOutputDevice outputDevice) : ITestFramework, IDataProducer, IOutputDeviceDataProducer +{ + // Set by the test to a path that does not exist yet. The test creates the file as soon as it + // observes LIVE_OUTPUT_STANDARD_OUTPUT on the standard output of 'dotnet test' while the + // command is still running, so this app can only see the file appear if its own console output + // really was forwarded live rather than buffered until it exits. + private const string SentinelPathEnvironmentVariable = "LIVE_OUTPUT_SENTINEL_PATH"; + + private static readonly TimeSpan SentinelTimeout = TimeSpan.FromSeconds(60); + + public string Uid => nameof(DummyTestAdapter); + + public string Version => "2.0.0"; + + public string DisplayName => nameof(DummyTestAdapter); + + public string Description => nameof(DummyTestAdapter); + + public Task IsEnabledAsync() => Task.FromResult(true); + + public Type[] DataTypesProduced => new[] { + typeof(TestNodeUpdateMessage) + }; + + public Task CreateTestSessionAsync(CreateTestSessionContext context) + => Task.FromResult(new CreateTestSessionResult() { IsSuccess = true }); + + public Task CloseTestSessionAsync(CloseTestSessionContext context) + => Task.FromResult(new CloseTestSessionResult() { IsSuccess = true }); + + public async Task ExecuteRequestAsync(ExecuteRequestContext context) + { + Console.WriteLine("LIVE_OUTPUT_STANDARD_OUTPUT"); + Console.Error.WriteLine("LIVE_OUTPUT_STANDARD_ERROR"); + + // Text written through the platform's output device does not reach the console directly: + // it is forwarded to 'dotnet test' over the pipe protocol and rendered by its reporter. + // Only durable session messages, warnings and errors cross the wire - plain informational + // text is deliberately discarded by the host under the pipe protocol. + await outputDevice.DisplayAsync(this, new SessionMessageOutputDeviceData("LIVE_OUTPUT_SESSION_MESSAGE"), context.CancellationToken); + await outputDevice.DisplayAsync(this, new WarningMessageOutputDeviceData("LIVE_OUTPUT_WARNING_MESSAGE"), context.CancellationToken); + await outputDevice.DisplayAsync(this, new ErrorMessageOutputDeviceData("LIVE_OUTPUT_ERROR_MESSAGE"), context.CancellationToken); + + string? failureReason = await WaitForOutputToBeObservedAsync(); + + await context.MessageBus.PublishAsync(this, new TestNodeUpdateMessage(context.Request.Session.SessionUid, new TestNode() + { + Uid = "Test0", + DisplayName = "Test0", + Properties = new PropertyBag(failureReason is null + ? new PassedTestNodeStateProperty("OK") + : new FailedTestNodeStateProperty(failureReason)), + })); + + context.Complete(); + } + + private static async Task WaitForOutputToBeObservedAsync() + { + string? sentinelPath = Environment.GetEnvironmentVariable(SentinelPathEnvironmentVariable); + if (string.IsNullOrEmpty(sentinelPath)) + { + return $"{SentinelPathEnvironmentVariable} is not set."; + } + + DateTime deadline = DateTime.UtcNow + SentinelTimeout; + while (DateTime.UtcNow < deadline) + { + if (File.Exists(sentinelPath)) + { + return null; + } + + await Task.Delay(50); + } + + return $"The standard output of this test app was not observed within {SentinelTimeout.TotalSeconds} seconds while it was still running, so it was not forwarded live."; + } +} diff --git a/test/TestAssets/TestProjects/TestProjectWithLiveOutput/TestProjectWithLiveOutput.csproj b/test/TestAssets/TestProjects/TestProjectWithLiveOutput/TestProjectWithLiveOutput.csproj new file mode 100644 index 000000000000..1ba237591546 --- /dev/null +++ b/test/TestAssets/TestProjects/TestProjectWithLiveOutput/TestProjectWithLiveOutput.csproj @@ -0,0 +1,18 @@ + + + + + $(CurrentTargetFramework) + Exe + + enable + enable + + false + true + + + + + + diff --git a/test/TestAssets/TestProjects/TestProjectWithLiveOutput/global.json b/test/TestAssets/TestProjects/TestProjectWithLiveOutput/global.json new file mode 100644 index 000000000000..9009caf0ba8f --- /dev/null +++ b/test/TestAssets/TestProjects/TestProjectWithLiveOutput/global.json @@ -0,0 +1,5 @@ +{ + "test": { + "runner": "Microsoft.Testing.Platform" + } +} diff --git a/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/Program.cs b/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/Program.cs new file mode 100644 index 000000000000..ca0c6837a4d2 --- /dev/null +++ b/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/Program.cs @@ -0,0 +1,53 @@ +using Microsoft.Testing.Platform.Builder; +using Microsoft.Testing.Platform.Capabilities.TestFramework; +using Microsoft.Testing.Platform.Extensions.Messages; +using Microsoft.Testing.Platform.Extensions.TestFramework; + +// This is the only console output the app produces, and it is written before the pipe handshake +// with 'dotnet test' can have completed. The SDK has to buffer it until it knows the negotiated +// protocol version and then flush it. Producing no further output afterwards is what makes this +// asset a guard: the flush cannot be masked by a later line flushing the whole buffer, and since +// the run succeeds the output is never replayed as part of a failure summary either. +Console.WriteLine("OUTPUT_BEFORE_HANDSHAKE"); + +var testApplicationBuilder = await TestApplication.CreateBuilderAsync(args); + +testApplicationBuilder.RegisterTestFramework(_ => new TestFrameworkCapabilities(), (_, __) => new DummyTestAdapter()); + +using var testApplication = await testApplicationBuilder.BuildAsync(); +return await testApplication.RunAsync(); + +public class DummyTestAdapter : ITestFramework, IDataProducer +{ + public string Uid => nameof(DummyTestAdapter); + + public string Version => "2.0.0"; + + public string DisplayName => nameof(DummyTestAdapter); + + public string Description => nameof(DummyTestAdapter); + + public Task IsEnabledAsync() => Task.FromResult(true); + + public Type[] DataTypesProduced => new[] { + typeof(TestNodeUpdateMessage) + }; + + public Task CreateTestSessionAsync(CreateTestSessionContext context) + => Task.FromResult(new CreateTestSessionResult() { IsSuccess = true }); + + public Task CloseTestSessionAsync(CloseTestSessionContext context) + => Task.FromResult(new CloseTestSessionResult() { IsSuccess = true }); + + public async Task ExecuteRequestAsync(ExecuteRequestContext context) + { + await context.MessageBus.PublishAsync(this, new TestNodeUpdateMessage(context.Request.Session.SessionUid, new TestNode() + { + Uid = "Test0", + DisplayName = "Test0", + Properties = new PropertyBag(new PassedTestNodeStateProperty("OK")), + })); + + context.Complete(); + } +} diff --git a/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/TestProjectWithOutputBeforeHandshake.csproj b/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/TestProjectWithOutputBeforeHandshake.csproj new file mode 100644 index 000000000000..1ba237591546 --- /dev/null +++ b/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/TestProjectWithOutputBeforeHandshake.csproj @@ -0,0 +1,18 @@ + + + + + $(CurrentTargetFramework) + Exe + + enable + enable + + false + true + + + + + + diff --git a/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/global.json b/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/global.json new file mode 100644 index 000000000000..9009caf0ba8f --- /dev/null +++ b/test/TestAssets/TestProjects/TestProjectWithOutputBeforeHandshake/global.json @@ -0,0 +1,5 @@ +{ + "test": { + "runner": "Microsoft.Testing.Platform" + } +} diff --git a/test/dotnet.Tests/CommandTests/Test/GivenDotnetTestForwardsTestHostOutput.cs b/test/dotnet.Tests/CommandTests/Test/GivenDotnetTestForwardsTestHostOutput.cs new file mode 100644 index 000000000000..025047df7066 --- /dev/null +++ b/test/dotnet.Tests/CommandTests/Test/GivenDotnetTestForwardsTestHostOutput.cs @@ -0,0 +1,135 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using CommandResult = Microsoft.DotNet.Cli.Utils.CommandResult; +using ExitCodes = Microsoft.NET.TestFramework.ExitCode; + +namespace Microsoft.DotNet.Cli.Test.Tests; + +/// +/// End-to-end coverage for https://github.com/dotnet/sdk/issues/51615: what a test application +/// writes to the console must reach the user while the run is in progress, and not only be +/// replayed when a test fails. +/// +[TestClass] +public class GivenDotnetTestForwardsTestHostOutput : SdkTest +{ + private const string SentinelPathEnvironmentVariable = "LIVE_OUTPUT_SENTINEL_PATH"; + private const string StandardOutputMarker = "LIVE_OUTPUT_STANDARD_OUTPUT"; + private const string StandardErrorMarker = "LIVE_OUTPUT_STANDARD_ERROR"; + private const string OutputDeviceSessionMessageMarker = "LIVE_OUTPUT_SESSION_MESSAGE"; + private const string OutputDeviceWarningMarker = "LIVE_OUTPUT_WARNING_MESSAGE"; + private const string OutputDeviceErrorMarker = "LIVE_OUTPUT_ERROR_MESSAGE"; + private const string OutputBeforeHandshakeMarker = "OUTPUT_BEFORE_HANDSHAKE"; + + [DataRow(TestingConstants.Debug)] + [DataRow(TestingConstants.Release)] + [TestMethod] + public void RunTestProjectWritingToConsole_ShouldForwardOutputWhileTheRunIsInProgress(string configuration) + { + TestAsset testInstance = TestAssetsManager.CopyTestAsset("TestProjectWithLiveOutput", Guid.NewGuid().ToString()) + .WithSource(); + + // The test app blocks until this file exists, and the file is only created once the + // marker it wrote has been observed on the live standard output of 'dotnet test'. + // An implementation that buffers the test app's output until it exits therefore + // deadlocks the app until its own timeout expires, which fails the run. + string sentinelPath = Path.Combine(testInstance.Path, "live-output-observed.sentinel"); + + Exception? sentinelFailure = null; + var command = new DotnetTestCommand(Log, disableNewOutput: false) + .WithWorkingDirectory(testInstance.Path) + .WithEnvironmentVariable(SentinelPathEnvironmentVariable, sentinelPath); + + // Execute retries the command on transient failures without re-copying the asset, so + // clear the sentinel on every attempt: a file left behind by an earlier attempt would + // let the app proceed immediately and quietly void what this test is proving. + // This runs after the command's process has started but before it is registered with + // the process reaper, so an exception escaping here would leave that process orphaned. + command.ProcessStartedHandler = _ => + { + try + { + File.Delete(sentinelPath); + } + catch (Exception ex) + { + sentinelFailure ??= ex; + } + }; + command.CommandOutputHandler = line => + { + if (line.Contains(StandardOutputMarker, StringComparison.Ordinal) && !File.Exists(sentinelPath)) + { + try + { + File.WriteAllText(sentinelPath, string.Empty); + } + catch (Exception ex) + { + // This runs on the only thread draining the command's standard output. + // Letting the exception escape would stop that drain and hang the run, so + // record it and let the assertion below report it. + sentinelFailure ??= ex; + } + } + }; + + CommandResult result = command.Execute("-c", configuration); + + sentinelFailure.Should().BeNull("the sentinel file should be writable and deletable"); + + // The run succeeds, so nothing replays the test app's output as part of a failure + // report: the markers can only be present because they were forwarded as produced. + // The output device markers additionally cover the text the test app routes through + // the platform's IOutputDevice, which reaches the SDK as protocol 1.3.0 display + // messages and is rendered at its informational, warning and error levels. + result.StdOut + .Should().Contain(StandardOutputMarker) + .And.Contain(StandardErrorMarker) + .And.Contain(OutputDeviceSessionMessageMarker) + .And.Contain(OutputDeviceWarningMarker) + .And.Contain(OutputDeviceErrorMarker); + + if (!SdkTestContext.IsLocalized()) + { + result.StdOut + .Should().Contain("Test run summary: Passed!") + .And.Contain("total: 1") + .And.Contain("succeeded: 1") + .And.Contain("failed: 0") + .And.Contain("skipped: 0"); + } + + result.ExitCode.Should().Be(ExitCodes.Success); + } + + [DataRow(TestingConstants.Debug)] + [DataRow(TestingConstants.Release)] + [TestMethod] + public void RunTestProjectWritingToConsoleBeforeHandshake_ShouldForwardOutputOnceProtocolIsNegotiated(string configuration) + { + TestAsset testInstance = TestAssetsManager.CopyTestAsset("TestProjectWithOutputBeforeHandshake", Guid.NewGuid().ToString()) + .WithSource(); + + CommandResult result = new DotnetTestCommand(Log, disableNewOutput: false) + .WithWorkingDirectory(testInstance.Path) + .Execute("-c", configuration); + + // The test app only writes before the handshake completes, so this output has to be + // buffered until the protocol version is known and then flushed. + result.StdOut.Should().Contain(OutputBeforeHandshakeMarker); + + if (!SdkTestContext.IsLocalized()) + { + result.StdOut + .Should().Contain("Test run summary: Passed!") + .And.Contain("total: 1") + .And.Contain("succeeded: 1") + .And.Contain("failed: 0") + .And.Contain("skipped: 0"); + } + + result.ExitCode.Should().Be(ExitCodes.Success); + } +}