diff --git a/src/Adapter/MSTestAdapter.PlatformServices/Execution/UnitTestRunner.cs b/src/Adapter/MSTestAdapter.PlatformServices/Execution/UnitTestRunner.cs index c98b5b546f..0dabc6c1ee 100644 --- a/src/Adapter/MSTestAdapter.PlatformServices/Execution/UnitTestRunner.cs +++ b/src/Adapter/MSTestAdapter.PlatformServices/Execution/UnitTestRunner.cs @@ -1,4 +1,4 @@ -// Copyright (c) Microsoft Corporation. All rights reserved. +// Copyright (c) Microsoft Corporation. All rights reserved. // Licensed under the MIT license. See LICENSE file in the project root for full license information. #if NETFRAMEWORK @@ -112,15 +112,62 @@ private static void ConfigureOutputRouting(TestOutputCaptureMode mode) Func modeProvider = static () => MSTestSettings.CurrentSettings.OutputCaptureMode; TextWriter originalOut = Console.Out; TextWriter originalError = Console.Error; - TestContextImplementation.ConfigureLiveOutputWriter(originalOut); + TextWriter liveOutputWriter = CreateLiveOutputWriter(Console.OpenStandardOutput(), Console.OutputEncoding); + TestContextImplementation.ConfigureLiveOutputWriter(liveOutputWriter); Console.SetOut(new ConsoleOutRouter(originalOut, modeProvider)); Console.SetError(new ConsoleErrorRouter(originalError, modeProvider)); - Trace.Listeners.Add(new TextWriterTraceListener(new TraceTextWriter(originalOut, modeProvider))); + Trace.Listeners.Add(new TextWriterTraceListener(new TraceTextWriter(liveOutputWriter, modeProvider))); s_outputRoutingInstalled = true; } } + internal static TextWriter CreateLiveOutputWriter(Stream standardOutput, Encoding encoding) + { + Encoding preamblelessEncoding = encoding.GetPreamble().Length == 0 + ? encoding + : new PreamblelessEncoding(encoding); + var streamWriter = new StreamWriter(standardOutput, preamblelessEncoding, bufferSize: 1024, leaveOpen: true) + { + AutoFlush = true, + }; + + return TextWriter.Synchronized(streamWriter); + } + + private sealed class PreamblelessEncoding(Encoding encoding) : Encoding + { + public override int CodePage => encoding.CodePage; + + public override string EncodingName => encoding.EncodingName; + + public override bool IsSingleByte => encoding.IsSingleByte; + + public override string WebName => encoding.WebName; + + public override Decoder GetDecoder() => encoding.GetDecoder(); + + public override Encoder GetEncoder() => encoding.GetEncoder(); + + public override int GetByteCount(char[] chars, int index, int count) + => encoding.GetByteCount(chars, index, count); + + public override int GetBytes(char[] chars, int charIndex, int charCount, byte[] bytes, int byteIndex) + => encoding.GetBytes(chars, charIndex, charCount, bytes, byteIndex); + + public override int GetCharCount(byte[] bytes, int index, int count) + => encoding.GetCharCount(bytes, index, count); + + public override int GetChars(byte[] bytes, int byteIndex, int byteCount, char[] chars, int charIndex) + => encoding.GetChars(bytes, byteIndex, byteCount, chars, charIndex); + + public override int GetMaxByteCount(int charCount) => encoding.GetMaxByteCount(charCount); + + public override int GetMaxCharCount(int byteCount) => encoding.GetMaxCharCount(byteCount); + + public override byte[] GetPreamble() => []; + } + #pragma warning disable CA1822 // Mark members as static public void Cancel() => PlatformServiceProvider.Instance.TestRunCancellationToken?.Cancel(); diff --git a/src/Adapter/MSTestAdapter.PlatformServices/InternalAPI/InternalAPI.Unshipped.txt b/src/Adapter/MSTestAdapter.PlatformServices/InternalAPI/InternalAPI.Unshipped.txt index 50a02b864d..daf928c571 100644 --- a/src/Adapter/MSTestAdapter.PlatformServices/InternalAPI/InternalAPI.Unshipped.txt +++ b/src/Adapter/MSTestAdapter.PlatformServices/InternalAPI/InternalAPI.Unshipped.txt @@ -35,6 +35,8 @@ Microsoft.VisualStudio.TestPlatform.MSTestAdapter.PlatformServices.TestContextIm static Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestMethodInfo.ParameterMetadataScanCount.get -> int static Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestMethodInfo.ResetParameterMetadataCacheForTesting() -> void static Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.TestMethodInfo.SetParameterMetadataScanCallbackForTesting(System.Action? callback) -> void +static Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution.UnitTestRunner.CreateLiveOutputWriter(System.IO.Stream! standardOutput, System.Text.Encoding! encoding) -> System.IO.TextWriter! static Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Helpers.RuntimeContext.IsMultiThreaded.get -> bool static Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.MSTestDiscovererHelpers.GetSettingsExceptionMessage(Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.ObjectModel.AdapterSettingsException! ex) -> string! static Microsoft.VisualStudio.TestPlatform.MSTestAdapter.PlatformServices.TestContextImplementation.ConfigureLiveOutputWriter(System.IO.TextWriter! liveOutputWriter) -> void +static Microsoft.VisualStudio.TestPlatform.MSTestAdapter.PlatformServices.TestContextImplementation.SetLiveOutputWriterForTesting(System.IO.TextWriter! liveOutputWriter) -> System.IDisposable! diff --git a/src/Adapter/MSTestAdapter.PlatformServices/Services/TestContextImplementation.LiveOutputScope.cs b/src/Adapter/MSTestAdapter.PlatformServices/Services/TestContextImplementation.LiveOutputScope.cs index 50793da52d..e6dc8e4115 100644 --- a/src/Adapter/MSTestAdapter.PlatformServices/Services/TestContextImplementation.LiveOutputScope.cs +++ b/src/Adapter/MSTestAdapter.PlatformServices/Services/TestContextImplementation.LiveOutputScope.cs @@ -23,10 +23,24 @@ internal void Deactivate() => Volatile.Write(ref _isActive, 0); } + private sealed class LiveOutputWriterScope(TextWriter? previousLiveOutputWriter) : IDisposable + { + public void Dispose() + => Volatile.Write(ref s_liveOutputWriter, previousLiveOutputWriter); + } + // This writer is captured together with the process-wide Console routers and shares their install-once lifetime. internal static void ConfigureLiveOutputWriter(TextWriter liveOutputWriter) => Volatile.Write(ref s_liveOutputWriter, liveOutputWriter); + internal static IDisposable SetLiveOutputWriterForTesting(TextWriter liveOutputWriter) + { + TextWriter? previousLiveOutputWriter = Volatile.Read(ref s_liveOutputWriter); + Volatile.Write(ref s_liveOutputWriter, liveOutputWriter); + + return new LiveOutputWriterScope(previousLiveOutputWriter); + } + private void WriteLive(string? message, bool appendLine) { if (_liveOutputWriter is null diff --git a/test/UnitTests/MSTestAdapter.PlatformServices.UnitTests/Execution/ConsoleRouterTests.cs b/test/UnitTests/MSTestAdapter.PlatformServices.UnitTests/Execution/ConsoleRouterTests.cs index 158f750473..0f77be3bae 100644 --- a/test/UnitTests/MSTestAdapter.PlatformServices.UnitTests/Execution/ConsoleRouterTests.cs +++ b/test/UnitTests/MSTestAdapter.PlatformServices.UnitTests/Execution/ConsoleRouterTests.cs @@ -17,6 +17,8 @@ namespace MSTestAdapter.PlatformServices.UnitTests.Execution; public class ConsoleRouterTests : TestContainer { + private static readonly TimeSpan WaitTimeout = TimeSpan.FromSeconds(5); + private readonly Mock _testMethod = new(); private TestContextImplementation CreateTestContext() @@ -165,4 +167,392 @@ public void TraceTextWriter_InNoneMode_DoesNotCapture() testContext.GetAndClearTrace().Should().BeNull(); console.ToString().Should().BeEmpty(); } + + public void LiveOutputWriterScope_RestoresPreviousWriter() + { + var firstWriter = new StringWriter(); + var secondWriter = new StringWriter(); + MSTestSettings.PopulateSettings( + """ + + + Live + + + """, + null, + null); + + try + { + using (TestContextImplementation.SetLiveOutputWriterForTesting(firstWriter)) + { + TestContextImplementation firstContext = CreateTestContext(); + using (TestContextImplementation.SetCurrentTestContext(firstContext)) + { + firstContext.WriteLine("first"); + } + + using (TestContextImplementation.SetLiveOutputWriterForTesting(secondWriter)) + { + TestContextImplementation secondContext = CreateTestContext(); + using (TestContextImplementation.SetCurrentTestContext(secondContext)) + { + secondContext.WriteLine("second"); + } + } + + TestContextImplementation restoredContext = CreateTestContext(); + using (TestContextImplementation.SetCurrentTestContext(restoredContext)) + { + restoredContext.WriteLine("restored"); + } + } + + firstWriter.ToString().Should().Contain("first").And.Contain("restored").And.NotContain("second"); + secondWriter.ToString().Should().Contain("second").And.NotContain("restored"); + } + finally + { + MSTestSettings.Reset(); + } + } + + public async Task LiveOutput_ConcurrentTestContextAndConsoleWrites_DoNotInvertConsoleWriterLocks() + { + TextWriter previousConsoleOut = Console.Out; + + MSTestSettings.PopulateSettings( + """ + + + Live + + + """, + null, + null); + + try + { + var capturedWriter = new LockCycleTextWriter(); + LockCycleResult capturedWriterResult = await RunLockCycleScenarioAsync( + capturedWriter, + capturedWriter, + testContext => testContext.WriteLine("test-context")); + capturedWriterResult.LockInversionObserved.Should().BeTrue( + "the controlled writer should reproduce the captured/current console lock inversion"); + + capturedWriter = new LockCycleTextWriter(); + var standardOutput = new ReentrantConsoleStream(); + TextWriter liveOutputWriter = UnitTestRunner.CreateLiveOutputWriter( + standardOutput, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: true)); + + LockCycleResult dedicatedWriterResult = await RunLockCycleScenarioAsync( + capturedWriter, + liveOutputWriter, + testContext => testContext.WriteLine("test-context")); + + dedicatedWriterResult.LockInversionObserved.Should().BeFalse( + "TestContext live output must not hold the captured console writer while the standard output stream consults Console.Out"); + dedicatedWriterResult.TestContextMessages.Should().Contain("test-context"); + dedicatedWriterResult.TestContextOutput.Should().Contain("console-logger"); + capturedWriter.Output.Should().Contain("console-logger").And.Contain("standard-output-write"); + standardOutput.Output.Should().NotStartWith("\uFEFF").And.Contain("test-context"); + } + finally + { + Console.SetOut(previousConsoleOut); + MSTestSettings.Reset(); + } + } + + public async Task LiveTrace_ConcurrentTraceAndConsoleWrites_DoNotInvertConsoleWriterLocks() + { + TextWriter previousConsoleOut = Console.Out; + MSTestSettings.PopulateSettings( + """ + + + Live + + + """, + null, + null); + + try + { + var capturedWriter = new LockCycleTextWriter(reenterCurrentConsoleOnFirstWrite: true); + var capturedTraceWriter = new TraceTextWriter(capturedWriter, Mode(TestOutputCaptureMode.Live)); + LockCycleResult capturedWriterResult = await RunLockCycleScenarioAsync( + capturedWriter, + capturedWriter, + _ => capturedTraceWriter.Write("trace")); + capturedWriterResult.LockInversionObserved.Should().BeTrue( + "the controlled writer should reproduce the trace/current console lock inversion"); + + capturedWriter = new LockCycleTextWriter(); + var standardOutput = new ReentrantConsoleStream(); + TextWriter liveOutputWriter = UnitTestRunner.CreateLiveOutputWriter( + standardOutput, + new UTF8Encoding(encoderShouldEmitUTF8Identifier: true)); + var dedicatedTraceWriter = new TraceTextWriter(liveOutputWriter, Mode(TestOutputCaptureMode.Live)); + + LockCycleResult dedicatedWriterResult = await RunLockCycleScenarioAsync( + capturedWriter, + liveOutputWriter, + _ => dedicatedTraceWriter.Write("trace")); + + dedicatedWriterResult.LockInversionObserved.Should().BeFalse( + "trace live output must not hold the captured console writer while the standard output stream consults Console.Out"); + dedicatedWriterResult.TraceOutput.Should().Contain("trace"); + capturedWriter.Output.Should().Contain("console-logger").And.Contain("standard-output-write"); + standardOutput.Output.Should().NotStartWith("\uFEFF").And.Contain("trace"); + } + finally + { + Console.SetOut(previousConsoleOut); + MSTestSettings.Reset(); + } + } + + private async Task RunLockCycleScenarioAsync( + LockCycleTextWriter capturedWriter, + TextWriter liveOutputWriter, + Action liveWrite) + { + using IDisposable liveOutputWriterScope = TestContextImplementation.SetLiveOutputWriterForTesting(liveOutputWriter); + TestContextImplementation testContext = CreateTestContext(); + Console.SetOut(new ConsoleOutRouter(capturedWriter, capturedWriter.EnterCurrentWriter)); + + try + { + using (TestContextImplementation.SetCurrentTestContext(testContext)) + { + var liveOutputWrite = Task.Run(() => liveWrite(testContext)); + + var firstWriterTimeout = Task.Delay(WaitTimeout); + Task firstWriterEntered = await Task.WhenAny( + capturedWriter.CapturedWriterEntered, + capturedWriter.CurrentWriterEntered, + firstWriterTimeout); + firstWriterEntered.Should().NotBeSameAs( + firstWriterTimeout, + "one output path should enter a console writer before the timeout"); + + var consoleLoggerWrite = Task.Run(() => Console.Write("console-logger")); + capturedWriter.ReleaseCurrentWriter(); + + var allWrites = Task.WhenAll(liveOutputWrite, consoleLoggerWrite); + Task completedTask = await Task.WhenAny(allWrites, Task.Delay(WaitTimeout)); + completedTask.Should().BeSameAs(allWrites, "both controlled output paths should complete"); + await allWrites; + } + + return new( + capturedWriter.LockInversionObserved, + testContext.GetDiagnosticMessages(), + testContext.GetAndClearOutput(), + testContext.GetAndClearTrace()); + } + finally + { + capturedWriter.ReleaseAll(); + } + } + + private sealed record LockCycleResult( + bool LockInversionObserved, + string? TestContextMessages, + string? TestContextOutput, + string? TraceOutput); + + private sealed class LockCycleTextWriter : TextWriter + { + private readonly bool _reenterCurrentConsoleOnFirstWrite; + private readonly object _capturedWriterLock = new(); + private readonly StringBuilder _output = new(); + private readonly TaskCompletionSource _capturedWriterEntered = new(TaskCreationOptions.RunContinuationsAsynchronously); + private readonly TaskCompletionSource _currentWriterEntered = new(TaskCreationOptions.RunContinuationsAsynchronously); + private readonly TaskCompletionSource _releaseCurrentWriter = new(TaskCreationOptions.RunContinuationsAsynchronously); + + private int _capturedWriterOwnerThreadId; + private int _currentWriterEntryCount; + private int _lockInversionObserved; + private int _writeReentryStarted; + + internal LockCycleTextWriter(bool reenterCurrentConsoleOnFirstWrite = false) + => _reenterCurrentConsoleOnFirstWrite = reenterCurrentConsoleOnFirstWrite; + + public override Encoding Encoding => Encoding.UTF8; + + internal Task CapturedWriterEntered => _capturedWriterEntered.Task; + + internal Task CurrentWriterEntered => _currentWriterEntered.Task; + + internal bool LockInversionObserved => Volatile.Read(ref _lockInversionObserved) == 1; + + internal string Output + { + get + { + lock (_capturedWriterLock) + { + return _output.ToString(); + } + } + } + + internal TestOutputCaptureMode EnterCurrentWriter() + { + if (Interlocked.Increment(ref _currentWriterEntryCount) == 1) + { + _currentWriterEntered.TrySetResult(null); + _releaseCurrentWriter.Task.GetAwaiter().GetResult(); + } + + return TestOutputCaptureMode.Live; + } + + internal void ReleaseCurrentWriter() + => _releaseCurrentWriter.TrySetResult(null); + + internal void ReleaseAll() + { + _currentWriterEntered.TrySetResult(null); + _releaseCurrentWriter.TrySetResult(null); + } + + public override void Write(string? value) + { + if (_reenterCurrentConsoleOnFirstWrite + && Interlocked.CompareExchange(ref _writeReentryStarted, 1, 0) == 0) + { + lock (_capturedWriterLock) + { + Volatile.Write(ref _capturedWriterOwnerThreadId, Environment.CurrentManagedThreadId); + try + { + _capturedWriterEntered.TrySetResult(null); + _currentWriterEntered.Task.GetAwaiter().GetResult(); + Console.Write("stream-writer-reentry"); + _output.Append(value); + } + finally + { + Volatile.Write(ref _capturedWriterOwnerThreadId, 0); + } + } + + return; + } + + if (!Monitor.TryEnter(_capturedWriterLock)) + { + if (Volatile.Read(ref _capturedWriterOwnerThreadId) != 0) + { + Volatile.Write(ref _lockInversionObserved, 1); + return; + } + + lock (_capturedWriterLock) + { + _output.Append(value); + } + + return; + } + + try + { + _output.Append(value); + } + finally + { + Monitor.Exit(_capturedWriterLock); + } + } + + public override void WriteLine(string? value) + { + lock (_capturedWriterLock) + { + Volatile.Write(ref _capturedWriterOwnerThreadId, Environment.CurrentManagedThreadId); + try + { + _capturedWriterEntered.TrySetResult(null); + _currentWriterEntered.Task.GetAwaiter().GetResult(); + + // Models the Unix StreamWriter/ConsolePal path consulting the current Console.Out + // while the originally captured synchronized writer is still held. + Console.Write("stream-writer-reentry"); + _output.AppendLine(value); + } + finally + { + Volatile.Write(ref _capturedWriterOwnerThreadId, 0); + } + } + } + } + + private sealed class ReentrantConsoleStream : Stream + { + private readonly MemoryStream _output = new(); + + internal string Output + { + get + { + lock (_output) + { + return Encoding.UTF8.GetString(_output.ToArray()); + } + } + } + + public override bool CanRead => false; + + public override bool CanSeek => false; + + public override bool CanWrite => true; + + public override long Length => throw new NotSupportedException(); + + public override long Position + { + get => throw new NotSupportedException(); + set + { + _ = value; + throw new NotSupportedException(); + } + } + + public override void Flush() + { + } + + public override int Read(byte[] buffer, int offset, int count) + => throw new NotSupportedException(); + + public override long Seek(long offset, SeekOrigin origin) + => throw new NotSupportedException(); + + public override void SetLength(long value) + => throw new NotSupportedException(); + + public override void Write(byte[] buffer, int offset, int count) + { + // Models ConsolePal.WriteFromConsoleStream consulting the current Console.Out. + Console.Write("standard-output-write"); + + lock (_output) + { + _output.Write(buffer, offset, count); + } + } + } }