From f8386230fbf3ef2ae78961f929ebf1cb70247e4b Mon Sep 17 00:00:00 2001 From: Andrew Arnott Date: Tue, 14 Sep 2021 11:36:31 -0600 Subject: [PATCH] Log test ID and simpler timestamp on test log messages --- .../MultiplexingStreamSeededChannelTests.cs | 6 ++--- .../MultiplexingStreamTests.cs | 6 ++--- src/Nerdbank.Streams.Tests/TestBase.cs | 22 ++++++++++++++----- .../XunitTraceListener.cs | 9 +++++--- 4 files changed, 28 insertions(+), 15 deletions(-) diff --git a/src/Nerdbank.Streams.Tests/MultiplexingStreamSeededChannelTests.cs b/src/Nerdbank.Streams.Tests/MultiplexingStreamSeededChannelTests.cs index 0821dd4a..9c012c9a 100644 --- a/src/Nerdbank.Streams.Tests/MultiplexingStreamSeededChannelTests.cs +++ b/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 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; }; diff --git a/src/Nerdbank.Streams.Tests/MultiplexingStreamTests.cs b/src/Nerdbank.Streams.Tests/MultiplexingStreamTests.cs index 082eebff..43146b2a 100644 --- a/src/Nerdbank.Streams.Tests/MultiplexingStreamTests.cs +++ b/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 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; }; diff --git a/src/Nerdbank.Streams.Tests/TestBase.cs b/src/Nerdbank.Streams.Tests/TestBase.cs index 374c4ce2..c98986bf 100644 --- a/src/Nerdbank.Streams.Tests/TestBase.cs +++ b/src/Nerdbank.Streams.Tests/TestBase.cs @@ -26,12 +26,19 @@ public abstract class TestBase : IDisposable private const bool WriteTestOutputToFile = false; + /// + /// Provides a unique number for each test that can be included in the log message. + /// + /// + /// Test logs can get misattributed to the wrong test, and prefixing each logged message with a number makes this detectable. + /// See this bug. + /// + 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; @@ -39,21 +46,24 @@ public abstract class TestBase : IDisposable 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; + /// - /// Gets the time the test has been running since its timeout timer started. + /// Gets a that started when the test class was instantiated. /// - 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(); diff --git a/src/Nerdbank.Streams.Tests/XunitTraceListener.cs b/src/Nerdbank.Streams.Tests/XunitTraceListener.cs index 717a6f38..d8496e5f 100644 --- a/src/Nerdbank.Streams.Tests/XunitTraceListener.cs +++ b/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(); } }