Why are messages sent to trace source missing from all but the first unit test?

I observe a weird behavior with Visual Studio Enterprise 2015 Update 1. When using logging through .NET Framework TraceSource inside the unit tests, only the first unit test contains the logging output.

This is the way to reproduce the issue:

An empty unit test project contains the UnitTest1 class which looks like this:

using System;
using System.Diagnostics;
using Microsoft.VisualStudio.TestTools.UnitTesting;

[TestClass]
public class UnitTest1
{
    private readonly TraceSource trace = new TraceSource("Demo", SourceLevels.All);

    [TestMethod]
    public void TestMethod1()
    {
        this.trace.TraceEvent(TraceEventType.Information, 0, "Test 1 (trace source)");
        Console.WriteLine("Test 1 (console)");
    }

    [TestMethod]
    public void TestMethod2()
    {
        this.trace.TraceEvent(TraceEventType.Information, 0, "Test 2 (trace source)");
        Console.WriteLine("Test 2 (console)");
    }
}

The App.config file looks like this:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.diagnostics>
    <trace autoflush="true" />
    <sources>
      <source name="Demo" switchValue="Critical, Error, Warning, ActivityTracing, Information, Verbose">
        <listeners>
          <add name="ConsoleTraceListener" />
          <add name="TextFileListener" />
        </listeners>
      </source>
    </sources>
    <sharedListeners>
      <add name="ConsoleTraceListener" type="System.Diagnostics.ConsoleTraceListener" />
      <add name="TextFileListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="tests.log" />
    </sharedListeners>
  </system.diagnostics>
</configuration>

When running the tests from Visual Studio:

The output of the first unit test is:

Test Name:  TestMethod1
Test Outcome:   Passed
Result StandardOutput:  
Demo Information: 0 : Test 1 (trace source)
Test 1 (console)

Both the messages from trace source and console are shown.

The output of the second unit test is:
```
Test Name:  TestMethod2
Test Outcome:   Passed
Result StandardOutput:  Test 2 (console)
```
While the output from Console.WriteLine works well, the one from TraceSource.TraceEvent is not shown.

Running the tests from the console by executing mstest /testcontainer:UnitTestProject1.dll reproduces the problem as well. The stdout reported for the first test contains two lines; the second test's stdout has one line only.

Why isn't logging traced for all but the very first test?

Solution

A workaround consists of wrapping the default TextWriter which uses the underlying Console.Out text writer to send the logs:

public class CustomTextWriter : TextWriter
{
    public override Encoding Encoding
    {
        get
        {
            return Console.Out.Encoding;
        }
    }

    public override void Write(string value)
    {
        Console.Out.Write(value);
    }

    public override void WriteLine(string value)
    {
        Console.Out.WriteLine(value);
    }
}

The writer is then used in a custom trace listener similar to one used in .NET Framework:

public class ConsoleTraceListener : TextWriterTraceListener
{
    public ConsoleTraceListener() : base(new CustomTextWriter())
    {
    }

    public override void Close()
    {
    }
}

which is declared in App.config like this:

<add name="ConsoleTraceListener"
     type="UnitTestProject1.ConsoleTraceListener, UnitTestProject1, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null" />

This produces the expected output, although it is still unclear why the problem exists in the first place. By checking Console.Out and the underlying stream, it doesn't seem that something gets disposed or closed after the first test ends (if it would, why would the current implementation of Out do nothing, and why would text sent to Console.WriteLine appear in logs?)