Merge branch 'testLoggingImprovements' into v2.8

src/Nerdbank.Streams.Tests/MultiplexingStreamSeededChannelTests.cs

@@ -42,14 +42,14 @@ public MultiplexingStreamSeededChannelTests(ITestOutputHelper logger)
         var mx1TraceSource = new TraceSource(nameof(this.mx1), SourceLevels.All);
         var mx2TraceSource = new TraceSource(nameof(this.mx2), SourceLevels.All);
 
-        mx1TraceSource.Listeners.Add(new XunitTraceListener(this.Logger));
-        mx2TraceSource.Listeners.Add(new XunitTraceListener(this.Logger));
+        mx1TraceSource.Listeners.Add(new XunitTraceListener(this.Logger, this.TestId, this.TestTimer));
+        mx2TraceSource.Listeners.Add(new XunitTraceListener(this.Logger, this.TestId, this.TestTimer));
 
         Func<string, MultiplexingStream.QualifiedChannelId, string, TraceSource> traceSourceFactory = (string mxInstanceName, MultiplexingStream.QualifiedChannelId id, string name) =>
         {
             var traceSource = new TraceSource(mxInstanceName + " channel " + id, SourceLevels.All);
             traceSource.Listeners.Clear(); // remove DefaultTraceListener
-            traceSource.Listeners.Add(new XunitTraceListener(this.Logger));
+            traceSource.Listeners.Add(new XunitTraceListener(this.Logger, this.TestId, this.TestTimer));
             return traceSource;
         };
 

src/Nerdbank.Streams.Tests/MultiplexingStreamTests.cs

@@ -41,14 +41,14 @@ public async Task InitializeAsync()
         var mx1TraceSource = new TraceSource(nameof(this.mx1), SourceLevels.All);
         var mx2TraceSource = new TraceSource(nameof(this.mx2), SourceLevels.All);
 
-        mx1TraceSource.Listeners.Add(new XunitTraceListener(this.Logger));
-        mx2TraceSource.Listeners.Add(new XunitTraceListener(this.Logger));
+        mx1TraceSource.Listeners.Add(new XunitTraceListener(this.Logger, this.TestId, this.TestTimer));
+        mx2TraceSource.Listeners.Add(new XunitTraceListener(this.Logger, this.TestId, this.TestTimer));
 
         Func<string, MultiplexingStream.QualifiedChannelId, string, TraceSource> traceSourceFactory = (string mxInstanceName, MultiplexingStream.QualifiedChannelId id, string name) =>
         {
             var traceSource = new TraceSource(mxInstanceName + " channel " + id, SourceLevels.All);
             traceSource.Listeners.Clear(); // remove DefaultTraceListener
-            traceSource.Listeners.Add(new XunitTraceListener(this.Logger));
+            traceSource.Listeners.Add(new XunitTraceListener(this.Logger, this.TestId, this.TestTimer));
             return traceSource;
         };
 

src/Nerdbank.Streams.Tests/TestBase.cs

@@ -26,34 +26,44 @@ public abstract class TestBase : IDisposable
 
     private const bool WriteTestOutputToFile = false;
 
+    /// <summary>
+    /// Provides a unique number for each test that can be included in the log message.
+    /// </summary>
+    /// <remarks>
+    /// Test logs can get misattributed to the wrong test, and prefixing each logged message with a number makes this detectable.
+    /// See <see href="https://github.com/microsoft/vstest/issues/3047">this bug</see>.
+    /// </remarks>
+    private static int testCounter;
+
     private readonly ProcessJobTracker processJobTracker = new ProcessJobTracker();
 
     private readonly CancellationTokenSource timeoutTokenSource;
 
-    private readonly Stopwatch testStopwatch;
-
     private readonly Random random = new Random();
 
     private CancellationTokenRegistration timeoutLoggerRegistration;
 
     protected TestBase(ITestOutputHelper logger)
     {
         this.Logger = WriteTestOutputToFile ? new FileLogger($@"d:\temp\test.{DateTime.Now:HH-mm-ss.ff}.log", logger) : logger;
-        this.testStopwatch = Stopwatch.StartNew();
         this.timeoutTokenSource = new CancellationTokenSource(TestTimeout);
         this.timeoutLoggerRegistration = this.timeoutTokenSource.Token.Register(() => logger.WriteLine("**Timeout token signaled** (Time index: {0:HH:mm:ss.ff}, Elapsed: {1})", DateTime.Now, this.ElapsedTime));
     }
 
     public static CancellationToken ExpectedTimeoutToken => new CancellationTokenSource(ExpectedTimeout).Token;
 
+    protected int TestId { get; } = Interlocked.Increment(ref testCounter);
+
     protected ITestOutputHelper Logger { get; }
 
     protected CancellationToken TimeoutToken => Debugger.IsAttached ? CancellationToken.None : this.timeoutTokenSource.Token;
 
+    protected TimeSpan ElapsedTime => this.TestTimer.Elapsed;
+
     /// <summary>
-    /// Gets the time the test has been running since its timeout timer started.
+    /// Gets a <see cref="Stopwatch"/> that started when the test class was instantiated.
     /// </summary>
-    protected TimeSpan ElapsedTime => this.testStopwatch.Elapsed;
+    protected Stopwatch TestTimer { get; } = Stopwatch.StartNew();
 
     private static TimeSpan TestTimeout => UnexpectedTimeout;
 
@@ -375,7 +385,7 @@ protected virtual void Dispose(bool disposing)
     {
         if (disposing)
         {
-            this.testStopwatch.Stop();
+            this.TestTimer.Stop();
             this.timeoutLoggerRegistration.Dispose();
             this.processJobTracker.Dispose();
             (this.Logger as IDisposable)?.Dispose();

src/Nerdbank.Streams.Tests/XunitTraceListener.cs

@@ -10,13 +10,16 @@
 internal class XunitTraceListener : TraceListener
 {
     private readonly ITestOutputHelper logger;
+    private readonly int testId;
     private readonly StringBuilder lineInProgress = new StringBuilder();
-    private readonly Stopwatch testRuntime = Stopwatch.StartNew();
+    private readonly Stopwatch testRuntime;
     private bool disposed;
 
-    internal XunitTraceListener(ITestOutputHelper logger)
+    internal XunitTraceListener(ITestOutputHelper logger, int testId, Stopwatch testTime)
     {
         this.logger = logger ?? throw new ArgumentNullException(nameof(logger));
+        this.testId = testId;
+        this.testRuntime = testTime;
     }
 
     public override bool IsThreadSafe => false;
@@ -111,7 +114,7 @@ public override void WriteLine(string message)
     {
         if (!this.disposed)
         {
-            this.logger.WriteLine($"{this.testRuntime.Elapsed} {this.lineInProgress}{message}");
+            this.logger.WriteLine($"[{this.testId,4} {this.testRuntime.Elapsed.TotalSeconds:00.00}] {this.lineInProgress}{message}");
             this.lineInProgress.Clear();
         }
     }