Improve test CI and reduce test log spam. (#6447)

Co-authored-by: Tayrtahn <tayrtahn@gmail.com>

.github/workflows/build-test.yml

@@ -28,4 +28,12 @@ jobs:
       - name: Build
         run: dotnet build --no-restore /p:WarningsAsErrors=nullable
       - name: Run tests
-        run: dotnet test --no-build -- NUnit.ConsoleOut=0
+        shell: pwsh
+        run: dotnet test --no-build -- NUnit.ConsoleOut=0 NUnit.TestOutputXml="logs" NUnit.WorkDirectory="$(pwd)/test_results"
+      - name: Archive NUnit3 test results.
+        if: always()
+        uses: actions/upload-artifact@v4
+        with:
+          name: nunit3-results-${{ matrix.os }}
+          path: test_results/*
+          retention-days: 7

.github/workflows/test-content.yml

@@ -35,8 +35,19 @@ jobs:
       - name: Install dependencies
         run: dotnet restore
       - name: Build
-        run: dotnet build --configuration Tools --no-restore
+        run: dotnet build --configuration DebugOpt --no-restore /m
       - name: Content.Tests
-        run: dotnet test --no-build Content.Tests/Content.Tests.csproj -v n
+        shell: pwsh
+        run: dotnet test --no-build --configuration DebugOpt Content.Tests/Content.Tests.csproj -- NUnit.ConsoleOut=0 NUnit.TestOutputXml="$(pwd)/test_results"
       - name: Content.IntegrationTests
-        run: COMPlus_gcServer=1 dotnet test --no-build Content.IntegrationTests/Content.IntegrationTests.csproj -v n
+        shell: pwsh
+        run: |
+          $env:DOTNET_gcServer=1
+          dotnet test --no-build --configuration DebugOpt Content.IntegrationTests/Content.IntegrationTests.csproj -- NUnit.ConsoleOut=0 NUnit.MapWarningTo=Failed NUnit.TestOutputXml="logs" NUnit.WorkDirectory="$(pwd)/test_results"
+      - name: Archive NUnit3 test results.
+        if: always()
+        uses: actions/upload-artifact@v4
+        with:
+          name: nunit3-results
+          path: test_results/*
+          retention-days: 7

RELEASE-NOTES.md

@@ -35,11 +35,25 @@ END TEMPLATE-->
 
 ### Breaking changes
 
+- ITestPair.Init() now requires a TextWriter be provided to write its gravestone to.
+  This gravestone is where TestPair test history is now written to.
+- ITestPair.AddToHistory() must be used to add tests to the test history.
+- Test history is now stored in ITestPair.ExtendedTestHistory.
+- Engine and content tests relying on TestPair using NUnit will now automatically
+  output gravestone files for test history. You should set the working directory for tests if you wish to
+  use these artifacts.
+- Using test pairs outside of a test environment without providing an `ITestContextLike` implementor will
+  now crash due to the lack of a running NUnit test. Use an `ExternalTestContext` for this use case.
+- Test logs no longer contain TestPair history.
+- Test history now includes the GC total memory usage at time of AddToHistory() call. This is typically while the test
+  is obtaining a pair.
+- ITestPair is now `[NotContentImplementable]` and future additions to the interface will not be considered breaking.
+- Erroneous logs in tests are now allowed to occur more than once, and assert a failure at the end of the test while doing pair cleanup instead of during it.
 - `Prototype<T>`, a precursor to `ProtoId<T>` used by toolshed, has been removed.
 
 ### New features
 
-*None yet*
+- TestPairs now automatically log their test history to a gravestone file.
 
 ### Bugfixes
 

Robust.Shared.IntegrationTests/Testing/EngineDummyTestPool.cs

@@ -0,0 +1,11 @@
+using Robust.UnitTesting.Pool;
+
+namespace Robust.UnitTesting.Shared.Testing;
+
+/// <summary>
+///     A test pool specifically for testing testpool and testpair behavior.
+/// </summary>
+internal sealed class EngineDummyTestPool : PoolManager<RobustIntegrationTest.TestPair>
+{
+
+}

Robust.Shared.IntegrationTests/Testing/EngineTestErrorLogFails.cs

@@ -0,0 +1,50 @@
+using NUnit.Framework;
+using Robust.UnitTesting.Pool;
+
+namespace Robust.UnitTesting.Shared.Testing;
+
+
+public sealed class EngineTestErrorLogFails
+{
+    [Test]
+    [Description("Asserts that Error level logs in a test pair instance do not throw, but do assert during CleanReturnAsync.")]
+    public async Task AssertErrorLoggingFailsTestCleanReturnAsync()
+    {
+        var pool = new EngineDummyTestPool();
+
+        pool.Startup();
+
+        var pair = await pool.GetPair();
+
+        // Log on both sides.. nothing should happen.
+        Assert.DoesNotThrow(() => pair.Server.Log.Error("Mogus"));
+        Assert.DoesNotThrow(() => pair.Client.Log.Error("Mogus"));
+
+        // But it should get very mad here.
+        Assert.ThrowsAsync<MultipleAssertException>(async () => await pair.CleanReturnAsync());
+
+        Assert.That(pair.State, NUnit.Framework.Is.EqualTo(PairState.Dead), "Expected the pair's return to result in its death.");
+
+        pool.Shutdown();
+    }
+
+    [Test]
+    [Description("Asserts that Error level logs in a test pair instance do not throw, but do assert during DirtyDispose.")]
+    public async Task AssertErrorLoggingFailsTestDirtyDispose()
+    {
+        var pool = new EngineDummyTestPool();
+
+        pool.Startup();
+
+        var pair = await pool.GetPair();
+
+        Assert.DoesNotThrow(() => pair.Server.Log.Error("Mogus"));
+        Assert.DoesNotThrow(() => pair.Client.Log.Error("Mogus"));
+
+        Assert.ThrowsAsync<MultipleAssertException>(async () => await pair.DisposeAsync());
+
+        Assert.That(pair.State, NUnit.Framework.Is.EqualTo(PairState.Dead), "Expected the pair's return to result in its death.");
+
+        pool.Shutdown();
+    }
+}

Robust.UnitTesting/Pool/ITestPair.cs

@@ -1,10 +1,13 @@
-using System.Collections.Generic;
+using System;
+using System.Collections.Generic;
 using System.IO;
+using System.Linq;
 using System.Threading.Tasks;
 using Robust.Shared.Timing;
 
 namespace Robust.UnitTesting.Pool;
 
+[NotContentImplementable]
 public interface ITestPair
 {
     int Id { get; }
@@ -12,7 +15,10 @@ public interface ITestPair
     public PairState State { get; }
     public bool Initialized { get; }
     void Kill();
-    List<string> TestHistory { get; }
+
+    [Obsolete("Constructed on the spot when needed, use ExtendedTestHistory instead.")]
+    List<string> TestHistory => ExtendedTestHistory.Select(x => x.TestName).ToList();
+    IReadOnlyList<TestHistoryEntry> ExtendedTestHistory { get; }
     PairSettings Settings { get; set; }
 
     int ServerSeed { get; }
@@ -23,11 +29,12 @@ public interface ITestPair
     void SetupSeed();
     void ClearModifiedCvars();
     void Use();
-    Task Init(int id, BasePoolManager manager, PairSettings settings, TextWriter testOut);
+    Task Init(int id, BasePoolManager manager, PairSettings settings, TextWriter testOut, TextWriter? gravestone);
     Task RecycleInternal(PairSettings next, TextWriter testOut);
     Task ApplySettings(PairSettings settings);
     Task RunTicksSync(int ticks);
     Task SyncTicks(int targetDelta = 1);
+    Task AddToHistory(string testName);
 }
 
 public enum PairState : byte

Robust.UnitTesting/Pool/NUnitTestContextWrap.cs

@@ -8,6 +8,7 @@ namespace Robust.UnitTesting.Pool;
 /// </summary>
 public sealed class NUnitTestContextWrap(TestContext context, TextWriter writer) : ITestContextLike
 {
-    public string FullName => context.Test.FullName;
+    public readonly TestContext Context = context;
+    public string FullName => Context.Test.FullName;
     public TextWriter Out => writer;
 }

Robust.UnitTesting/Pool/PoolManager.cs

@@ -7,6 +7,7 @@ using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
 using NUnit.Framework;
+using NUnit.Framework.Internal;
 using Robust.Shared;
 using Robust.Shared.Timing;
 using Robust.Shared.Utility;
@@ -15,6 +16,14 @@ namespace Robust.UnitTesting.Pool;
 
 public abstract class BasePoolManager
 {
+    /// <summary>
+    ///     Stores a global count for pair IDs, so they're unique across the entire run regardless of how many pools we
+    ///     create and use.
+    ///
+    ///     This ensures things like gravestone files are truly unique.
+    /// </summary>
+    internal static int PairIdCounter = 0;
+
     internal abstract void Return(ITestPair pair);
     public abstract Assembly[] ClientAssemblies { get; }
     public abstract Assembly[] ServerAssemblies { get; }
@@ -35,7 +44,6 @@ public abstract class BasePoolManager
 [Virtual]
 public class PoolManager<TPair> : BasePoolManager where TPair : class, ITestPair, new()
 {
-    private int _nextPairId;
     private readonly Lock _pairLock = new();
     private bool _initialized;
 
@@ -128,10 +136,10 @@ public class PoolManager<TPair> : BasePoolManager where TPair : class, ITestPair
             foreach (var pair in pairs)
             {
                 var borrowed = Pairs[pair];
-                builder.AppendLine($"Pair {pair.Id}, Tests Run: {pair.TestHistory.Count}, Borrowed: {borrowed}");
-                for (var i = 0; i < pair.TestHistory.Count; i++)
+                builder.AppendLine($"Pair {pair.Id}, Tests Run: {pair.ExtendedTestHistory.Count}, Borrowed: {borrowed}");
+                for (var i = 0; i < pair.ExtendedTestHistory.Count; i++)
                 {
-                    builder.AppendLine($"#{i}: {pair.TestHistory[i]}");
+                    builder.AppendLine($"#{i}: {pair.ExtendedTestHistory[i]}");
                 }
             }
 
@@ -158,64 +166,49 @@ public class PoolManager<TPair> : BasePoolManager where TPair : class, ITestPair
         var watch = new Stopwatch();
         await testOut.WriteLineAsync($"{nameof(GetPair)}: Called by test {currentTestName}");
         TPair? pair = null;
-        try
+        watch.Start();
+        if (settings.MustBeNew)
         {
-            watch.Start();
-            if (settings.MustBeNew)
+            await testOut.WriteLineAsync(
+                $"{nameof(GetPair)}: Creating pair, because settings of pool settings");
+            pair = await CreateServerClientPair(settings, testContext, testOut);
+        }
+        else
+        {
+            await testOut.WriteLineAsync($"{nameof(GetPair)}: Looking in pool for a suitable pair");
+            pair = GrabOptimalPair(settings);
+            if (pair != null)
             {
-                await testOut.WriteLineAsync(
-                    $"{nameof(GetPair)}: Creating pair, because settings of pool settings");
-                pair = await CreateServerClientPair(settings, testOut);
-            }
-            else
-            {
-                await testOut.WriteLineAsync($"{nameof(GetPair)}: Looking in pool for a suitable pair");
-                pair = GrabOptimalPair(settings);
-                if (pair != null)
+                pair.ActivateContext(testOut);
+                await testOut.WriteLineAsync($"{nameof(GetPair)}: Suitable pair found");
+
+                if (pair.Settings.CanFastRecycle(settings))
                 {
-                    pair.ActivateContext(testOut);
-                    await testOut.WriteLineAsync($"{nameof(GetPair)}: Suitable pair found");
-
-                    if (pair.Settings.CanFastRecycle(settings))
-                    {
-                        await testOut.WriteLineAsync($"{nameof(GetPair)}: Cleanup not needed, Skipping cleanup of pair");
-                        await pair.ApplySettings(settings);
-                    }
-                    else
-                    {
-                        await testOut.WriteLineAsync($"{nameof(GetPair)}: Cleaning existing pair");
-                        await pair.RecycleInternal(settings, testOut);
-                    }
-
-                    await pair.RunTicksSync(5);
-                    await pair.SyncTicks(targetDelta: 1);
+                    await testOut.WriteLineAsync($"{nameof(GetPair)}: Cleanup not needed, Skipping cleanup of pair");
+                    await pair.ApplySettings(settings);
                 }
                 else
                 {
-                    await testOut.WriteLineAsync($"{nameof(GetPair)}: Creating a new pair, no suitable pair found in pool");
-                    pair = await CreateServerClientPair(settings, testOut);
+                    await testOut.WriteLineAsync($"{nameof(GetPair)}: Cleaning existing pair");
+                    await pair.RecycleInternal(settings, testOut);
                 }
+
+                await pair.RunTicksSync(5);
+                await pair.SyncTicks(targetDelta: 1);
             }
-        }
-        finally
-        {
-            if (pair != null && pair.TestHistory.Count > 0)
+            else
             {
-                await testOut.WriteLineAsync($"{nameof(GetPair)}: Pair {pair.Id} Test History Start");
-                for (var i = 0; i < pair.TestHistory.Count; i++)
-                {
-                    await testOut.WriteLineAsync($"- Pair {pair.Id} Test #{i}: {pair.TestHistory[i]}");
-                }
-                await testOut.WriteLineAsync($"{nameof(GetPair)}: Pair {pair.Id} Test History End");
+                await testOut.WriteLineAsync($"{nameof(GetPair)}: Creating a new pair, no suitable pair found in pool");
+                pair = await CreateServerClientPair(settings, testContext, testOut);
             }
         }
 
         await testOut.WriteLineAsync($"{nameof(GetPair)}: Retrieving pair {pair.Id} from pool took {watch.Elapsed.TotalMilliseconds} ms");
 
+        await pair.AddToHistory(currentTestName);
         pair.ValidateSettings(settings);
         pair.ClearModifiedCvars();
         pair.Settings = settings;
-        pair.TestHistory.Add(currentTestName);
         pair.SetupSeed();
 
         await testOut.WriteLineAsync($"{nameof(GetPair)}: Returning pair {pair.Id} with client/server seeds: {pair.ClientSeed}/{pair.ServerSeed}");
@@ -290,13 +283,18 @@ we are just going to end this here to save a lot of time. This is the exception
         }
     }
 
-    private async Task<TPair> CreateServerClientPair(PairSettings settings, TextWriter testOut)
+    private async Task<TPair> CreateServerClientPair(PairSettings settings, ITestContextLike context, TextWriter testOut)
     {
         try
         {
-            var id = Interlocked.Increment(ref _nextPairId);
+            var id = Interlocked.Increment(ref PairIdCounter);
             var pair = new TPair();
-            await pair.Init(id, this, settings, testOut);
+
+            TextWriter? gravestone = null;
+            if (context is NUnitTestContextWrap)
+                gravestone = File.CreateText($"{TestContext.CurrentContext.WorkDirectory}/gravestone-{id}.txt");
+
+            await pair.Init(id, this, settings, testOut, gravestone);
             pair.Use();
             await pair.RunTicksSync(5);
             await pair.SyncTicks(targetDelta: 1);

Robust.UnitTesting/Pool/PoolTestLogHandler.cs

@@ -1,4 +1,5 @@
 using System;
+using System.Collections.Generic;
 using System.IO;
 using NUnit.Framework;
 using Robust.Shared.Log;
@@ -12,8 +13,7 @@ namespace Robust.UnitTesting.Pool;
 /// </summary>
 /// <remarks>
 /// <para>
-/// This class logs to two places: an NUnit <see cref="TestContext"/>  (so it nicely gets attributed to a test in your IDE),
-/// and an in-memory ring buffer for diagnostic purposes. If test pooling breaks, the ring buffer can be used to see what the broken instance has gone through.
+/// This class logs to one place: an NUnit <see cref="TestContext"/> (so it nicely gets attributed to a test in your IDE)
 /// </para>
 /// <para>
 /// The active test context can be swapped out so pooled instances can correctly have their logs attributed.
@@ -29,6 +29,10 @@ public sealed class PoolTestLogHandler : ILogHandler
 
     public LogLevel? FailureLevel { get; set; }
 
+    public IReadOnlyList<string> FailingLogs => _failingLogs;
+
+    private readonly List<string> _failingLogs = new();
+
     public PoolTestLogHandler(string? prefix)
     {
         _prefix = prefix != null ? $"{prefix}: " : "";
@@ -36,6 +40,18 @@ public sealed class PoolTestLogHandler : ILogHandler
 
     public bool ShuttingDown;
 
+    /// <summary>
+    /// <para>
+    ///     Event handler that allows you to override a potential failing log.
+    ///     Use this if you want to allow certain error logs to be considered passing.
+    /// </para>
+    /// <para>
+    ///     Has the sawmill name and <see cref="LogEvent"/> passed in, and should return a boolean
+    ///     <see langword="true"/> when the log message should not be logged as a failure.
+    /// </para>
+    /// </summary>
+    public event Func<string, LogEvent, bool>? JudgeLog;
+
     public void Log(string sawmillName, LogEvent message)
     {
         var level = message.Level.ToRobust();
@@ -57,16 +73,17 @@ public sealed class PoolTestLogHandler : ILogHandler
 
         testContext.WriteLine(line);
 
-        if (FailureLevel == null || level < FailureLevel)
+        if (FailureLevel == null || level < FailureLevel || (JudgeLog?.Invoke(sawmillName, message) ?? false))
             return;
 
         testContext.Flush();
-        Assert.Fail($"{line} Exception: {message.Exception}");
+        _failingLogs.Add($"{line} Exception: {message.Exception}");
     }
 
     public void ClearContext()
     {
         ActiveContext = null;
+        _failingLogs.Clear();
     }
 
     public void ActivateContext(TextWriter context)

Robust.UnitTesting/Pool/TestHistoryEntry.cs

@@ -0,0 +1,25 @@
+namespace Robust.UnitTesting.Pool;
+
+public sealed class TestHistoryEntry
+{
+    /// <summary>
+    ///     The name of the test.
+    /// </summary>
+    public readonly string TestName;
+
+    /// <summary>
+    ///     The amount of memory the GC claims to be using at the time of adding this entry.
+    /// </summary>
+    public readonly long TimeOfUseMemoryTotal;
+
+    internal TestHistoryEntry(string testName, long timeOfUseMemoryTotal)
+    {
+        TestName = testName;
+        TimeOfUseMemoryTotal = timeOfUseMemoryTotal;
+    }
+
+    public override string ToString()
+    {
+        return $"{TestName} (started at {TimeOfUseMemoryTotal} bytes allocated.)";
+    }
+}

Robust.UnitTesting/Pool/TestPair.Helpers.cs

@@ -4,6 +4,7 @@ using System.Diagnostics.CodeAnalysis;
 using System.Linq;
 using System.Threading.Tasks;
 using NUnit.Framework;
+using Robust.Client.Timing;
 using Robust.Shared.GameObjects;
 using Robust.Shared.Map;
 using Robust.Shared.Prototypes;
@@ -201,6 +202,31 @@ public partial class TestPair<TServer, TClient>
         await RunTicksSync(SecondsToTicks(seconds));
     }
 
+
+    /// <summary>
+    ///     Runs the pairs just long enough for PVS to send entities, ensuring the client's current tick is what the
+    ///     server's was at call time.
+    /// </summary>
+    public async Task RunUntilSynced()
+    {
+        if (Client.Session is null)
+        {
+            // Already synced, because the client isn't connected so we have nothing *to* sync.
+            // Run a tick on server.
+            await Server.WaitRunTicks(1);
+            return;
+        }
+
+        var sGameTiming = Server.Timing;
+        var cGameTiming = (IClientGameTiming)Client.Timing;
+        var startTime = sGameTiming.CurTick;
+
+        while (cGameTiming.LastRealTick < startTime)
+        {
+            await RunTicksSync(1);
+        }
+    }
+
     /// <summary>
     /// Runs the server-client pair in sync, but also ensures they are both idle each tick.
     /// </summary>

Robust.UnitTesting/Pool/TestPair.Recycle.cs

@@ -1,8 +1,11 @@
 using System;
 using System.IO;
 using System.Linq;
+using System.Threading;
 using System.Threading.Tasks;
+using JetBrains.Annotations;
 using NUnit.Framework;
+using NUnit.Framework.Internal;
 using Robust.Client;
 using Robust.Shared;
 using Robust.Shared.Exceptions;
@@ -15,6 +18,22 @@ namespace Robust.UnitTesting.Pool;
 // This partial file contains logic related to recycling & disposing test pairs.
 public partial class TestPair<TServer, TClient>
 {
+    private void ReportErrorLogs()
+    {
+        using (Assert.EnterMultipleScope())
+        {
+            if (ServerLogHandler.FailingLogs.Count == 1)
+                Assert.Fail(ServerLogHandler.FailingLogs[0]);
+            else if (ServerLogHandler.FailingLogs.Count > 1)
+                Assert.Fail("Server had multiple failing logs reported, consult the game log.");
+
+            if (ClientLogHandler.FailingLogs.Count == 1)
+                Assert.Fail(ClientLogHandler.FailingLogs[0]);
+            else if (ClientLogHandler.FailingLogs.Count > 1)
+                Assert.Fail("Client had multiple failing logs reported, consult the game log.");
+        }
+    }
+
     private async Task OnDirtyDispose()
     {
         var usageTime = Watch.Elapsed;
@@ -23,6 +42,7 @@ public partial class TestPair<TServer, TClient>
         Kill();
         var disposeTime = Watch.Elapsed;
         await TestOut.WriteLineAsync($"{nameof(DisposeAsync)}: Disposed pair {Id} in {disposeTime.TotalMilliseconds} ms");
+        ReportErrorLogs();
         // Test pairs should only dirty dispose if they are failing. If they are not failing, this probably happened
         // because someone forgot to clean-return the pair.
         Assert.Warn("Test was dirty-disposed.");
@@ -71,18 +91,32 @@ public partial class TestPair<TServer, TClient>
             return;
         }
 
-        var sRuntimeLog = Server.Resolve<IRuntimeLog>();
-        if (sRuntimeLog.ExceptionCount > 0)
-            throw new Exception($"{nameof(CleanReturnAsync)}: Server logged exceptions");
-        var cRuntimeLog = Client.Resolve<IRuntimeLog>();
-        if (cRuntimeLog.ExceptionCount > 0)
-            throw new Exception($"{nameof(CleanReturnAsync)}: Client logged exceptions");
+        try
+        {
+            var sRuntimeLog = Server.Resolve<IRuntimeLog>();
+            if (sRuntimeLog.ExceptionCount > 0)
+                throw new Exception($"{nameof(CleanReturnAsync)}: Server logged exceptions");
+            var cRuntimeLog = Client.Resolve<IRuntimeLog>();
+            if (cRuntimeLog.ExceptionCount > 0)
+                throw new Exception($"{nameof(CleanReturnAsync)}: Client logged exceptions");
+
+            ReportErrorLogs();
+        }
+        catch (Exception)
+        {
+            Kill();
+            await ReallyBeIdle();
+            await TestOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: Dirty disposed in {Watch.Elapsed.TotalMilliseconds} ms");
+            Assert.Warn("Test was dirty-disposed.");
+            throw;
+        }
 
         var returnTime = Watch.Elapsed;
         await TestOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: PoolManager took {returnTime.TotalMilliseconds} ms to put pair {Id} back into the pool");
         State = PairState.Ready;
     }
 
+    [HandlesResourceDisposal]
     public async ValueTask CleanReturnAsync()
     {
         if (State != PairState.InUse)
@@ -90,10 +124,16 @@ public partial class TestPair<TServer, TClient>
 
         await TestOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: Return of pair {Id} started");
         State = PairState.CleanDisposed;
-        await OnCleanDispose();
-        DebugTools.Assert(State is PairState.Dead or PairState.Ready);
-        Manager.Return(this);
-        ClearContext();
+        try
+        {
+            await OnCleanDispose();
+        }
+        finally
+        {
+            DebugTools.Assert(State is PairState.Dead or PairState.Ready);
+            ClearContext();
+            Manager.Return(this);
+        }
     }
 
     public async ValueTask DisposeAsync()
@@ -105,9 +145,15 @@ public partial class TestPair<TServer, TClient>
                 break;
             case PairState.InUse:
                 await TestOut.WriteLineAsync($"{nameof(DisposeAsync)}: Dirty return of pair {Id} started");
-                await OnDirtyDispose();
-                Manager.Return(this);
-                ClearContext();
+                try
+                {
+                    await OnDirtyDispose();
+                }
+                finally
+                {
+                    ClearContext();
+                    Manager.Return(this);
+                }
                 break;
             default:
                 throw new Exception($"{nameof(DisposeAsync)}: Unexpected state. Pair: {Id}. State: {State}.");

Robust.UnitTesting/Pool/TestPair.cs

@@ -1,7 +1,9 @@
 using System;
 using System.Collections.Generic;
 using System.IO;
+using System.Text;
 using System.Threading.Tasks;
+using NUnit.Framework;
 using Robust.Shared.Configuration;
 using Robust.Shared.Player;
 using Robust.Shared.Prototypes;
@@ -23,8 +25,11 @@ public abstract partial class TestPair<TServer, TClient> : ITestPair, IAsyncDisp
     public PairState State { get; private set; } = PairState.Ready;
     public bool Initialized { get; private set; }
     protected TextWriter TestOut = default!;
+    protected TextWriter? Gravestone = default!;
     public Stopwatch Watch { get; } = new();
-    public List<string> TestHistory { get; } = new();
+
+    private List<TestHistoryEntry> _testHistory = new();
+    public IReadOnlyList<TestHistoryEntry> ExtendedTestHistory => _testHistory;
     public PairSettings Settings { get; set; } = default!;
 
     public readonly PoolTestLogHandler ServerLogHandler = new("SERVER");
@@ -57,7 +62,8 @@ public abstract partial class TestPair<TServer, TClient> : ITestPair, IAsyncDisp
         int id,
         BasePoolManager manager,
         PairSettings settings,
-        TextWriter testOut)
+        TextWriter testOut,
+        TextWriter? gravestone)
     {
         if (Initialized)
             throw new InvalidOperationException("Already initialized");
@@ -66,6 +72,10 @@ public abstract partial class TestPair<TServer, TClient> : ITestPair, IAsyncDisp
         Manager = manager;
         Settings = settings;
         Initialized = true;
+        Gravestone = gravestone;
+
+        if (Gravestone is not null)
+            await Gravestone.WriteLineAsync("Test pair initialized.");
 
         ClientLogHandler.ActivateContext(testOut);
         ServerLogHandler.ActivateContext(testOut);
@@ -112,6 +122,10 @@ public abstract partial class TestPair<TServer, TClient> : ITestPair, IAsyncDisp
         ClientLogHandler.ShuttingDown = true;
         Server.Dispose();
         Client.Dispose();
+
+        Gravestone?.WriteLine("Test pair killed.");
+        Gravestone?.WriteLine(Environment.StackTrace);
+        Gravestone?.Flush();
     }
 
     private void ClearContext()
@@ -123,6 +137,9 @@ public abstract partial class TestPair<TServer, TClient> : ITestPair, IAsyncDisp
 
     public void ActivateContext(TextWriter testOut)
     {
+        // This is the very, very first thing that happens in prepping a pair, so wait a sec
+        // for disposal to get to finish if we got returned right this instant.
+        // Not necessary after some of the disposal changes but defensive is good.
         TestOut = testOut;
         ServerLogHandler.ActivateContext(testOut);
         ClientLogHandler.ActivateContext(testOut);
@@ -132,9 +149,22 @@ public abstract partial class TestPair<TServer, TClient> : ITestPair, IAsyncDisp
     {
         if (State != PairState.Ready)
             throw new InvalidOperationException($"Pair is not ready to use. State: {State}");
+
         State = PairState.InUse;
     }
 
+    public async Task AddToHistory(string testName)
+    {
+        var memUse = GC.GetTotalMemory(false);
+        var entry = new TestHistoryEntry(testName, memUse);
+        _testHistory.Add(entry);
+        if (Gravestone is not null)
+        {
+            await Gravestone.WriteLineAsync($"#{_testHistory.Count}: {entry}");
+            await Gravestone.FlushAsync();
+        }
+    }
+
     public void SetupSeed()
     {
         var sRand = Server.Resolve<IRobustRandom>();