Skip to content

Commit

Permalink
Fix debug output clear (#1014)
Browse files Browse the repository at this point in the history 
* Make getting string and clearing run under the same lock
  • Loading branch information
@nohwnd
nohwnd authored Dec 2, 2021
1 parent 3904a64 commit 7109e59
Show file tree
Hide file tree
Showing 19 changed files with 540 additions and 351 deletions.
27 changes: 27 additions & 0 deletions TestFx.sln
View file
Original file line number Diff line number Diff line change
Expand Up @@ -222,6 +222,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "DiscoverInternalsProject",
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "PlatformServices.Desktop.Legacy", "src\Adapter\PlatformServices.Desktop.Legacy\PlatformServices.Desktop.Legacy.csproj", "{F64A748C-DDBA-4B57-99F4-D9E55684A7A4}"
EndProject
Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "OutputTestProject", "test\E2ETests\TestAssets\OutputTestProject\OutputTestProject.csproj", "{66608D86-416A-49AF-A937-C47F7E4586AE}"
EndProject
Global
GlobalSection(SharedMSBuildProjectFiles) = preSolution
src\Adapter\PlatformServices.Shared\PlatformServices.Shared.projitems*{2177c273-ae07-43b3-b87a-443e47a23c5a}*SharedItemsImports = 13
Expand Down Expand Up @@ -1348,6 +1350,30 @@ Global
{F64A748C-DDBA-4B57-99F4-D9E55684A7A4}.Release|x64.Build.0 = Release|Any CPU
{F64A748C-DDBA-4B57-99F4-D9E55684A7A4}.Release|x86.ActiveCfg = Release|Any CPU
{F64A748C-DDBA-4B57-99F4-D9E55684A7A4}.Release|x86.Build.0 = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|Any CPU.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|Any CPU.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|ARM.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|ARM.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|x64.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|x64.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|x86.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Code Analysis Debug|x86.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|Any CPU.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|ARM.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|ARM.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|x64.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|x64.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|x86.ActiveCfg = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Debug|x86.Build.0 = Debug|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|Any CPU.ActiveCfg = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|Any CPU.Build.0 = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|ARM.ActiveCfg = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|ARM.Build.0 = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|x64.ActiveCfg = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|x64.Build.0 = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|x86.ActiveCfg = Release|Any CPU
{66608D86-416A-49AF-A937-C47F7E4586AE}.Release|x86.Build.0 = Release|Any CPU
EndGlobalSection
GlobalSection(SolutionProperties) = preSolution
HideSolutionNode = FALSE
Expand Down Expand Up @@ -1420,6 +1446,7 @@ Global
{6B4DE65C-4162-4C52-836A-8F9FA901814A} = {D53BD452-F69F-4FB3-8B98-386EDA28A4C8}
{44A504D9-A0D6-427D-BFB2-DB144A74F0D5} = {D53BD452-F69F-4FB3-8B98-386EDA28A4C8}
{F64A748C-DDBA-4B57-99F4-D9E55684A7A4} = {24088844-2107-4DB2-8F3F-CBCA94FC4B28}
{66608D86-416A-49AF-A937-C47F7E4586AE} = {D53BD452-F69F-4FB3-8B98-386EDA28A4C8}
EndGlobalSection
GlobalSection(ExtensibilityGlobals) = postSolution
SolutionGuid = {31E0F4D5-975A-41CC-933E-545B2201FAF9}
Expand Down
149 changes: 76 additions & 73 deletions src/Adapter/MSTest.CoreAdapter/Execution/LogMessageListener.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ namespace Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution
using System;
using System.Globalization;
using System.IO;
using System.Threading;
using Microsoft.VisualStudio.TestPlatform.MSTestAdapter.PlatformServices;
using Microsoft.VisualStudio.TestPlatform.MSTestAdapter.PlatformServices.Interface;
using Microsoft.VisualStudio.TestTools.UnitTesting.Logging;
Expand All @@ -16,21 +17,23 @@ namespace Microsoft.VisualStudio.TestPlatform.MSTest.TestAdapter.Execution
/// </summary>
public class LogMessageListener : IDisposable
{
private static LogMessageListener activeRedirector;
private readonly LogMessageListener previousRedirector;
private readonly ThreadSafeStringWriter redirectLoggerOut;
private readonly ThreadSafeStringWriter redirectStdErr;
private readonly bool captureDebugTraces;
private static object traceLock = new object();
private static int listenerCount;
private static ThreadSafeStringWriter redirectedDebugTrace;

/// <summary>
/// Trace listener to capture Trace.WriteLines in the test cases
/// </summary>
private ITraceListener traceListener;
private static ITraceListener traceListener;
private readonly ThreadSafeStringWriter redirectedStandardOutput;
private readonly ThreadSafeStringWriter redirectedStandardError;
private readonly bool captureDebugTraces;

/// <summary>
/// Trace listener Manager to perform operation on tracelistener objects.
/// </summary>
private ITraceListenerManager traceListenerManager;
private bool isDisposed;

/// <summary>
/// Initializes a new instance of the <see cref="LogMessageListener"/> class.
Expand All @@ -41,30 +44,43 @@ public LogMessageListener(bool captureDebugTraces)
this.captureDebugTraces = captureDebugTraces;

// Cache the original output/error streams and replace it with the own stream.
this.redirectLoggerOut = new ThreadSafeStringWriter(CultureInfo.InvariantCulture, "out");
this.redirectStdErr = new ThreadSafeStringWriter(CultureInfo.InvariantCulture, "err");

Logger.OnLogMessage += this.redirectLoggerOut.WriteLine;
this.redirectedStandardOutput = new ThreadSafeStringWriter(CultureInfo.InvariantCulture, "out");
this.redirectedStandardError = new ThreadSafeStringWriter(CultureInfo.InvariantCulture, "err");

// Cache the previous redirector if any and replace the trace listener.
this.previousRedirector = activeRedirector;
Logger.OnLogMessage += this.redirectedStandardOutput.WriteLine;

if (this.captureDebugTraces)
{
this.traceListener = PlatformServiceProvider.Instance.GetTraceListener(new ThreadSafeStringWriter(CultureInfo.InvariantCulture, "trace"));
this.traceListenerManager = PlatformServiceProvider.Instance.GetTraceListenerManager(this.redirectLoggerOut, this.redirectStdErr);

// If there was a previous LogMessageListener active, remove its
// TraceListener (it will be restored when this one is disposed).
if (this.previousRedirector != null && this.previousRedirector.traceListener != null)
// This is awkward, it has a side-effect of setting up Console output redirection, but the naming is suggesting that we are
// just getting TraceListener manager.
this.traceListenerManager = PlatformServiceProvider.Instance.GetTraceListenerManager(this.redirectedStandardOutput, this.redirectedStandardError);

// The Debug listener uses Debug.WriteLine and Debug.Write to write the messages, which end up written into Trace.Listeners.
// These listeners are static and hence shared across the whole process. We need to capture Debug output only for the current
// test, which was historically done by registering a listener in constructor of this class, and by removing the listener on Dispose.
// The newly created listener replaced previously registered listener, which was remembered, and put back on dispose.
//
// This works well as long as there are no tests running in parallel. But as soon as there are tests running in parallel. Then all the
// debug output of all tests will be output into the test that was most recently created (because it registered the listener most recently).
//
// To prevent mixing of outputs, the ThreadSafeStringWriter was re-implemented for net46 and newer to leverage AsyncLocal, which allows the writer to
// write only to the output of the current test. This leaves the LogMessageListener with only one task. Make sure that a trace listener is registered
// as long as there is any active test. This is still done by constructor and Dispose, but instead of replacing the listener every time, we use listenerCount
// to only add the listerner when there is none, and remove it when we are the last one to dispose.
//
// This would break the behavior for net451, but that functionality was moved further into ThreadSafeStringWriter.
lock (traceLock)
{
this.traceListenerManager.Remove(this.previousRedirector.traceListener);
}
if (listenerCount == 0)
{
redirectedDebugTrace = new ThreadSafeStringWriter(CultureInfo.InvariantCulture, "trace");
traceListener = PlatformServiceProvider.Instance.GetTraceListener(redirectedDebugTrace);
this.traceListenerManager.Add(traceListener);
}

this.traceListenerManager.Add(this.traceListener);
listenerCount++;
}
}

activeRedirector = this;
}

~LogMessageListener()
Expand All @@ -75,12 +91,12 @@ public LogMessageListener(bool captureDebugTraces)
/// <summary>
/// Gets logger output
/// </summary>
public string StandardOutput => this.redirectLoggerOut.ToString();
public string StandardOutput => this.redirectedStandardOutput.ToString();

/// <summary>
/// Gets 'Error' Output from the redirected stream
/// </summary>
public string StandardError => this.redirectStdErr.ToString();
public string StandardError => this.redirectedStandardError.ToString();

/// <summary>
/// Gets 'Trace' Output from the redirected stream
Expand All @@ -89,43 +105,31 @@ public string DebugTrace
{
get
{
return (this.traceListener == null || this.traceListener.GetWriter() == null) ?
string.Empty : this.traceListener.GetWriter().ToString();
return redirectedDebugTrace?.ToString();
}
}

public string GetAndClearStandardOutput()
{
var output = this.redirectLoggerOut.ToString();
this.redirectLoggerOut.Clear();
var output = this.redirectedStandardOutput.ToStringAndClear();
return output;
}

public string GetAndClearStandardError()
{
var output = this.redirectStdErr.ToString();
this.redirectStdErr.Clear();
var output = this.redirectedStandardError.ToStringAndClear();
return output;
}

public string GetAndClearDebugTrace()
{
var writer = this.traceListener?.GetWriter();
if (writer == null)
if (redirectedDebugTrace == null)
{
return null;
}

if (writer is StringWriter sw)
{
var sb = sw.GetStringBuilder();
var output = sb?.ToString();
sb?.Clear();
return output;
}

// we cannot clear it because it is just a text writer
return writer.ToString();
var output = redirectedDebugTrace.ToStringAndClear();
return output;
}

public void Dispose()
Expand All @@ -136,47 +140,46 @@ public void Dispose()

private void Dispose(bool disposing)
{
if (disposing)
if (disposing && !this.isDisposed)
{
Logger.OnLogMessage -= this.redirectLoggerOut.WriteLine;
Logger.OnLogMessage -= this.redirectStdErr.WriteLine;
this.isDisposed = true;
Logger.OnLogMessage -= this.redirectedStandardOutput.WriteLine;
Logger.OnLogMessage -= this.redirectedStandardError.WriteLine;

this.redirectLoggerOut.Dispose();
this.redirectStdErr.Dispose();
this.redirectedStandardOutput.Dispose();
this.redirectedStandardError.Dispose();

if (this.captureDebugTraces)
{
try
lock (traceLock)
{
if (this.traceListener != null)
{
this.traceListenerManager.Remove(this.traceListener);
}

// Restore the previous LogMessageListener's TraceListener (if there was one)
if (this.previousRedirector != null && this.previousRedirector.traceListener != null)
if (listenerCount == 1)
{
this.traceListenerManager.Add(this.previousRedirector.traceListener);
try
{
if (traceListener != null)
{
this.traceListenerManager.Remove(traceListener);
}
}
catch (Exception e)
{
// Catch all exceptions since Dispose should not throw.
PlatformServiceProvider.Instance.AdapterTraceLogger.LogError("ConsoleOutputRedirector.Dispose threw exception: {0}", e);
}

if (traceListener != null)
{
// Dispose trace manager and listeners
this.traceListenerManager.Dispose(traceListener);
this.traceListenerManager = null;
traceListener = null;
}
}
}
catch (Exception e)
{
// Catch all exceptions since Dispose should not throw.
PlatformServiceProvider.Instance.AdapterTraceLogger.LogError(
"ConsoleOutputRedirector.Dispose threw exception: {0}",
e);
}

if (this.traceListener != null)
{
// Dispose trace manager and listeners
this.traceListenerManager.Dispose(this.traceListener);
this.traceListenerManager = null;
this.traceListener = null;
listenerCount--;
}
}

activeRedirector = this.previousRedirector;
}
}
}
Expand Down
19 changes: 10 additions & 9 deletions src/Adapter/PlatformServices.Desktop/Services/DesktopTestContextImplementation.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,7 @@ public class TestContextImplementation : UTF.TestContext, ITestContext
/// <summary>
/// Writer on which the messages given by the user should be written
/// </summary>
private StringWriter stringWriter;
private ThreadSafeStringWriter threadSafeStringWriter;

/// <summary>
/// Specifies whether the writer is disposed or not
Expand Down Expand Up @@ -80,7 +80,9 @@ public TestContextImplementation(ITestMethod testMethod, StringWriter stringWrit
Debug.Assert(properties != null, "properties is not null");

this.testMethod = testMethod;
this.stringWriter = stringWriter;

// Cannot get this type in constructor directly, because all sigantures for all platforms need to be the same.
this.threadSafeStringWriter = (ThreadSafeStringWriter)stringWriter;
this.properties = new Dictionary<string, object>(properties);
this.CancellationTokenSource = new CancellationTokenSource();
this.InitializeProperties();
Expand Down Expand Up @@ -283,7 +285,7 @@ public override void Write(string message)
try
{
var msg = message?.Replace("\0", "\\0");
this.stringWriter.Write(msg);
this.threadSafeStringWriter.Write(msg);
}
catch (ObjectDisposedException)
{
Expand All @@ -307,7 +309,7 @@ public override void Write(string format, params object[] args)
try
{
string message = string.Format(CultureInfo.CurrentCulture, format?.Replace("\0", "\\0"), args);
this.stringWriter.Write(message);
this.threadSafeStringWriter.Write(message);
}
catch (ObjectDisposedException)
{
Expand All @@ -330,7 +332,7 @@ public override void WriteLine(string message)
try
{
var msg = message?.Replace("\0", "\\0");
this.stringWriter.WriteLine(msg);
this.threadSafeStringWriter.WriteLine(msg);
}
catch (ObjectDisposedException)
{
Expand All @@ -354,7 +356,7 @@ public override void WriteLine(string format, params object[] args)
try
{
string message = string.Format(CultureInfo.CurrentCulture, format?.Replace("\0", "\\0"), args);
this.stringWriter.WriteLine(message);
this.threadSafeStringWriter.WriteLine(message);
}
catch (ObjectDisposedException)
{
Expand Down Expand Up @@ -446,16 +448,15 @@ public IList<string> GetResultFiles()
/// <returns>The test context messages added so far.</returns>
public string GetDiagnosticMessages()
{
return this.stringWriter.ToString();
return this.threadSafeStringWriter.ToString();
}

/// <summary>
/// Clears the previous testContext writeline messages.
/// </summary>
public void ClearDiagnosticMessages()
{
var sb = this.stringWriter.GetStringBuilder();
sb?.Remove(0, sb.Length);
this.threadSafeStringWriter.ToStringAndClear();
}

#endregion
Expand Down
Loading

0 comments on commit 7109e59

Please # to comment.