Test pooling diagnostic fixes. (#14349)

Co-authored-by: metalgearsloth <31366439+metalgearsloth@users.noreply.github.com>
Co-authored-by: metalgearsloth <comedian_vs_clown@hotmail.com>

Content.IntegrationTests/PoolManager.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.IO;
 using System.Linq;
 using System.Text;
 using System.Threading;
@@ -39,21 +40,22 @@ namespace Content.IntegrationTests;
 /// </summary>
 public static class PoolManager
 {
-    private static readonly (string cvar, string value, bool tryAdd)[] ServerTestCvars =
+    private static readonly (string cvar, string value)[] ServerTestCvars =
     {
-        (CCVars.DatabaseSynchronous.Name, "true", false),
+        // @formatter:off
-        (CCVars.DatabaseSqliteDelay.Name, "0", false),
+        (CCVars.DatabaseSynchronous.Name,     "true"),
-        (CCVars.HolidaysEnabled.Name, "false", false),
+        (CCVars.DatabaseSqliteDelay.Name,     "0"),
-        (CCVars.GameMap.Name, "Empty", true),
+        (CCVars.HolidaysEnabled.Name,         "false"),
-        (CCVars.AdminLogsQueueSendDelay.Name, "0", true),
+        (CCVars.GameMap.Name,                 "Empty"),
-        (CCVars.NetPVS.Name, "false", true),
+        (CCVars.AdminLogsQueueSendDelay.Name, "0"),
-        (CCVars.NPCMaxUpdates.Name, "999999", true),
+        (CVars.NetPVS.Name,                   "false"),
-        (CCVars.SysWinTickPeriod.Name, "0", true),
+        (CCVars.NPCMaxUpdates.Name,           "999999"),
-        (CCVars.ThreadParallelCount.Name, "1", true),
+        (CVars.ThreadParallelCount.Name,      "1"),
-        (CCVars.GameRoleTimers.Name, "false", false),
+        (CCVars.GameRoleTimers.Name,          "false"),
-        (CCVars.CargoShuttles.Name, "false", false),
+        (CCVars.CargoShuttles.Name,           "false"),
-        (CCVars.EmergencyShuttleEnabled.Name, "false", false),
+        (CCVars.EmergencyShuttleEnabled.Name, "false"),
-        (CCVars.ProcgenPreload.Name, "false", false),
+        (CCVars.ProcgenPreload.Name,          "false"),
+        // @formatter:on
     };
 
     private static int PairId;
@@ -76,7 +78,9 @@ public static class PoolManager
         });
     }
 
-    private static async Task<RobustIntegrationTest.ServerIntegrationInstance> GenerateServer(PoolSettings poolSettings)
+    private static async Task<(RobustIntegrationTest.ServerIntegrationInstance, PoolTestLogHandler)> GenerateServer(
+        PoolSettings poolSettings,
+        TextWriter testOut)
     {
         var options = new RobustIntegrationTest.ServerIntegrationOptions
         {
@@ -112,11 +116,16 @@ public static class PoolManager
             IoCManager.Resolve<ILogManager>().GetSawmill("loc").Level = LogLevel.Error;
         };
 
+        var logHandler = new PoolTestLogHandler("SERVER");
+        logHandler.ActivateContext(testOut);
+
+        options.OverrideLogHandler = () => logHandler;
+
         SetupCVars(poolSettings, options);
 
         var server = new RobustIntegrationTest.ServerIntegrationInstance(options);
         await server.WaitIdleAsync();
-        return server;
+        return (server, logHandler);
     }
 
     /// <summary>
@@ -160,7 +169,9 @@ public static class PoolManager
         }
     }
 
-    private static async Task<RobustIntegrationTest.ClientIntegrationInstance> GenerateClient(PoolSettings poolSettings)
+    private static async Task<(RobustIntegrationTest.ClientIntegrationInstance, PoolTestLogHandler)> GenerateClient(
+        PoolSettings poolSettings,
+        TextWriter testOut)
     {
         var options = new RobustIntegrationTest.ClientIntegrationOptions
         {
@@ -202,11 +213,15 @@ public static class PoolManager
             });
         };
 
+        var logHandler = new PoolTestLogHandler("CLIENT");
+        logHandler.ActivateContext(testOut);
+        options.OverrideLogHandler = () => logHandler;
+
         SetupCVars(poolSettings, options);
 
         var client = new RobustIntegrationTest.ClientIntegrationInstance(options);
         await client.WaitIdleAsync();
-        return client;
+        return (client, logHandler);
     }
 
     private static void SetupCVars(PoolSettings poolSettings, RobustIntegrationTest.IntegrationOptions options)
@@ -225,7 +240,7 @@ public static class PoolManager
 
         if (poolSettings.DisableInterpolate)
         {
-            options.CVarOverrides[CCVars.NetInterp.Name] = "false";
+            options.CVarOverrides[CVars.NetInterp.Name] = "false";
         }
 
         if (poolSettings.Map != null)
@@ -248,51 +263,56 @@ public static class PoolManager
     public static async Task<PairTracker> GetServerClient(PoolSettings poolSettings = null) =>
         await GetServerClientPair(poolSettings ?? new PoolSettings());
 
-    private static string GetDefaultTestName()
+    private static string GetDefaultTestName(TestContext testContext)
     {
-        return TestContext.CurrentContext.Test.FullName
+        return testContext.Test.FullName.Replace("Content.IntegrationTests.Tests.", "");
-            .Replace("Content.IntegrationTests.Tests.", "");
     }
 
     private static async Task<PairTracker> GetServerClientPair(PoolSettings poolSettings)
     {
+        // Trust issues with the AsyncLocal that backs this.
+        var testContext = TestContext.CurrentContext;
+        var testOut = TestContext.Out;
+
         DieIfPoolFailure();
-        var currentTestName = poolSettings.TestName ?? GetDefaultTestName();
+        var currentTestName = poolSettings.TestName ?? GetDefaultTestName(testContext);
         var poolRetrieveTimeWatch = new Stopwatch();
-        await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Called by test {currentTestName}");
+        await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Called by test {currentTestName}");
         Pair pair = null;
         try
         {
             poolRetrieveTimeWatch.Start();
             if (poolSettings.MustBeNew)
             {
-                await TestContext.Out.WriteLineAsync(
+                await testOut.WriteLineAsync(
                     $"{nameof(GetServerClientPair)}: Creating pair, because settings of pool settings");
-                pair = await CreateServerClientPair(poolSettings);
+                pair = await CreateServerClientPair(poolSettings, testOut);
             }
             else
             {
-                await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Looking in pool for a suitable pair");
+                await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Looking in pool for a suitable pair");
                 pair = GrabOptimalPair(poolSettings);
                 if (pair != null)
                 {
-                    await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Suitable pair found");
+                    pair.ActivateContext(testOut);
+
+                    await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Suitable pair found");
                     var canSkip = pair.Settings.CanFastRecycle(poolSettings);
 
                     if (canSkip)
                     {
-                        await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Cleanup not needed, Skipping cleanup of pair");
+                        await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Cleanup not needed, Skipping cleanup of pair");
                     }
                     else
                     {
-                        await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Cleaning existing pair");
+                        await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Cleaning existing pair");
-                        await CleanPooledPair(poolSettings, pair);
+                        await CleanPooledPair(poolSettings, pair, testOut);
                     }
                 }
                 else
                 {
-                    await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Creating a new pair, no suitable pair found in pool");
+                    await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Creating a new pair, no suitable pair found in pool");
-                    pair = await CreateServerClientPair(poolSettings);
+                    pair = await CreateServerClientPair(poolSettings, testOut);
                 }
             }
 
@@ -301,24 +321,25 @@ public static class PoolManager
         {
             if (pair != null && pair.TestHistory.Count > 1)
             {
-                await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Pair {pair.PairId} Test History Start");
+                await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Pair {pair.PairId} Test History Start");
                 for (int i = 0; i < pair.TestHistory.Count; i++)
                 {
-                    await TestContext.Out.WriteLineAsync($"- Pair {pair.PairId} Test #{i}: {pair.TestHistory[i]}");
+                    await testOut.WriteLineAsync($"- Pair {pair.PairId} Test #{i}: {pair.TestHistory[i]}");
                 }
-                await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Pair {pair.PairId} Test History End");
+                await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Pair {pair.PairId} Test History End");
             }
         }
         var poolRetrieveTime = poolRetrieveTimeWatch.Elapsed;
-        await TestContext.Out.WriteLineAsync(
+        await testOut.WriteLineAsync(
             $"{nameof(GetServerClientPair)}: Retrieving pair {pair.PairId} from pool took {poolRetrieveTime.TotalMilliseconds} ms");
-        await TestContext.Out.WriteLineAsync(
+        await testOut.WriteLineAsync(
             $"{nameof(GetServerClientPair)}: Returning pair {pair.PairId}");
         pair.Settings = poolSettings;
         pair.TestHistory.Add(currentTestName);
         var usageWatch = new Stopwatch();
         usageWatch.Start();
-        return new PairTracker
+
+        return new PairTracker(testOut)
         {
             Pair = pair,
             UsageWatch = usageWatch
@@ -370,11 +391,11 @@ public static class PoolManager
         }
     }
 
-    private static async Task CleanPooledPair(PoolSettings poolSettings, Pair pair)
+    private static async Task CleanPooledPair(PoolSettings poolSettings, Pair pair, TextWriter testOut)
     {
         var methodWatch = new Stopwatch();
         methodWatch.Start();
-        await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Setting CVar ");
+        await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Setting CVar ");
         var configManager = pair.Server.ResolveDependency<IConfigurationManager>();
         await pair.Server.WaitPost(() =>
         {
@@ -383,7 +404,7 @@ public static class PoolManager
         var cNetMgr = pair.Client.ResolveDependency<IClientNetManager>();
         if (!cNetMgr.IsConnected)
         {
-            await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Connecting client, and restarting server");
+            await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Connecting client, and restarting server");
             pair.Client.SetConnectTarget(pair.Server);
             await pair.Server.WaitPost(() =>
             {
@@ -396,7 +417,7 @@ public static class PoolManager
         }
         await ReallyBeIdle(pair,11);
 
-        await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Disconnecting client, and restarting server");
+        await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Disconnecting client, and restarting server");
 
         await pair.Client.WaitPost(() =>
         {
@@ -407,7 +428,7 @@ public static class PoolManager
 
         if (!string.IsNullOrWhiteSpace(pair.Settings.ExtraPrototypes))
         {
-            await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Removing prototypes");
+            await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Removing prototypes");
             if (!pair.Settings.NoServer)
             {
                 var serverProtoManager = pair.Server.ResolveDependency<IPrototypeManager>();
@@ -430,7 +451,7 @@ public static class PoolManager
 
         if (poolSettings.ExtraPrototypes != null)
         {
-            await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Adding prototypes");
+            await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Adding prototypes");
             if (!poolSettings.NoServer)
             {
                 await ConfigurePrototypes(pair.Server, poolSettings);
@@ -441,7 +462,7 @@ public static class PoolManager
             }
         }
 
-        await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Restarting server again");
+        await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Restarting server again");
         await pair.Server.WaitPost(() =>
         {
             EntitySystem.Get<GameTicker>().RestartRound();
@@ -450,7 +471,7 @@ public static class PoolManager
 
         if (!poolSettings.NotConnected)
         {
-            await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Connecting client");
+            await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Connecting client");
             await ReallyBeIdle(pair);
             pair.Client.SetConnectTarget(pair.Server);
             await pair.Client.WaitPost(() =>
@@ -463,7 +484,7 @@ public static class PoolManager
             });
         }
         await ReallyBeIdle(pair);
-        await TestContext.Out.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Done recycling");
+        await testOut.WriteLineAsync($"Recycling: {methodWatch.Elapsed.TotalMilliseconds} ms: Done recycling");
     }
 
     private static void DieIfPoolFailure()
@@ -485,14 +506,21 @@ we are just going to end this here to save a lot of time. This is the exception
             Assert.Fail("The pool was shut down");
         }
     }
-    private static async Task<Pair> CreateServerClientPair(PoolSettings poolSettings)
+    private static async Task<Pair> CreateServerClientPair(PoolSettings poolSettings, TextWriter testOut)
     {
         Pair pair;
         try
         {
-            var client = await GenerateClient(poolSettings);
+            var (client, clientLog) = await GenerateClient(poolSettings, testOut);
-            var server = await GenerateServer(poolSettings);
+            var (server, serverLog) = await GenerateServer(poolSettings, testOut);
-            pair = new Pair { Server = server, Client = client, PairId = Interlocked.Increment(ref PairId) };
+            pair = new Pair
+            {
+                Server = server,
+                ServerLogHandler = serverLog,
+                Client = client,
+                ClientLogHandler = clientLog,
+                PairId = Interlocked.Increment(ref PairId)
+            };
         }
         catch (Exception ex)
         {
@@ -780,12 +808,27 @@ public sealed class Pair
     public RobustIntegrationTest.ServerIntegrationInstance Server { get; init; }
     public RobustIntegrationTest.ClientIntegrationInstance Client { get; init; }
 
+    public PoolTestLogHandler ServerLogHandler { get; init; }
+    public PoolTestLogHandler ClientLogHandler { get; init; }
+
     public void Kill()
     {
         Dead = true;
         Server.Dispose();
         Client.Dispose();
     }
+
+    public void ClearContext()
+    {
+        ServerLogHandler.ClearContext();
+        ClientLogHandler.ClearContext();
+    }
+
+    public void ActivateContext(TextWriter testOut)
+    {
+        ServerLogHandler.ActivateContext(testOut);
+        ClientLogHandler.ActivateContext(testOut);
+    }
 }
 
 /// <summary>
@@ -793,24 +836,32 @@ public sealed class Pair
 /// </summary>
 public sealed class PairTracker : IAsyncDisposable
 {
+    private readonly TextWriter _testOut;
     private int _disposed;
+    public Stopwatch UsageWatch { get; set; }
+    public Pair Pair { get; init; }
+
+    public PairTracker(TextWriter testOut)
+    {
+        _testOut = testOut;
+    }
 
     private async Task OnDirtyDispose()
     {
         var usageTime = UsageWatch.Elapsed;
-        await TestContext.Out.WriteLineAsync($"{nameof(DisposeAsync)}: Test gave back pair {Pair.PairId} in {usageTime.TotalMilliseconds} ms");
+        await _testOut.WriteLineAsync($"{nameof(DisposeAsync)}: Test gave back pair {Pair.PairId} in {usageTime.TotalMilliseconds} ms");
         var dirtyWatch = new Stopwatch();
         dirtyWatch.Start();
         Pair.Kill();
         PoolManager.NoCheckReturn(Pair);
         var disposeTime = dirtyWatch.Elapsed;
-        await TestContext.Out.WriteLineAsync($"{nameof(DisposeAsync)}: Disposed pair {Pair.PairId} in {disposeTime.TotalMilliseconds} ms");
+        await _testOut.WriteLineAsync($"{nameof(DisposeAsync)}: Disposed pair {Pair.PairId} in {disposeTime.TotalMilliseconds} ms");
     }
 
     private async Task OnCleanDispose()
     {
         var usageTime = UsageWatch.Elapsed;
-        await TestContext.Out.WriteLineAsync($"{nameof(CleanReturnAsync)}: Test borrowed pair {Pair.PairId} for {usageTime.TotalMilliseconds} ms");
+        await _testOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: Test borrowed pair {Pair.PairId} for {usageTime.TotalMilliseconds} ms");
         var cleanWatch = new Stopwatch();
         cleanWatch.Start();
         // Let any last minute failures the test cause happen.
@@ -834,20 +885,22 @@ public sealed class PairTracker : IAsyncDisposable
             PoolManager.NoCheckReturn(Pair);
             await PoolManager.ReallyBeIdle(Pair);
             var returnTime2 = cleanWatch.Elapsed;
-            await TestContext.Out.WriteLineAsync($"{nameof(CleanReturnAsync)}: Clean disposed in {returnTime2.TotalMilliseconds} ms");
+            await _testOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: Clean disposed in {returnTime2.TotalMilliseconds} ms");
             return;
         }
 
         var sRuntimeLog = Pair.Server.ResolveDependency<IRuntimeLog>();
-        if (sRuntimeLog.ExceptionCount > 0) throw new Exception($"{nameof(CleanReturnAsync)}: Server logged exceptions");
+        if (sRuntimeLog.ExceptionCount > 0)
+            throw new Exception($"{nameof(CleanReturnAsync)}: Server logged exceptions");
         var cRuntimeLog = Pair.Client.ResolveDependency<IRuntimeLog>();
-        if (cRuntimeLog.ExceptionCount > 0) throw new Exception($"{nameof(CleanReturnAsync)}: Client logged exceptions");
+        if (cRuntimeLog.ExceptionCount > 0)
+            throw new Exception($"{nameof(CleanReturnAsync)}: Client logged exceptions");
+
+        Pair.ClearContext();
         PoolManager.NoCheckReturn(Pair);
         var returnTime = cleanWatch.Elapsed;
-        await TestContext.Out.WriteLineAsync($"{nameof(CleanReturnAsync)}: PoolManager took {returnTime.TotalMilliseconds} ms to put pair {Pair.PairId} back into the pool");
+        await _testOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: PoolManager took {returnTime.TotalMilliseconds} ms to put pair {Pair.PairId} back into the pool");
     }
-    public Stopwatch UsageWatch { get; set; }
-    public Pair Pair { get; init; }
 
     public async ValueTask CleanReturnAsync()
     {
@@ -855,7 +908,7 @@ public sealed class PairTracker : IAsyncDisposable
         switch (disposed)
         {
             case 0:
-                await TestContext.Out.WriteLineAsync($"{nameof(CleanReturnAsync)}: Return of pair {Pair.PairId} started");
+                await _testOut.WriteLineAsync($"{nameof(CleanReturnAsync)}: Return of pair {Pair.PairId} started");
                 break;
             case 1:
                 throw new Exception($"{nameof(CleanReturnAsync)}: Already clean returned");
@@ -874,10 +927,10 @@ public sealed class PairTracker : IAsyncDisposable
         switch (disposed)
         {
             case 0:
-                await TestContext.Out.WriteLineAsync($"{nameof(DisposeAsync)}: Dirty return of pair {Pair.PairId} started");
+                await _testOut.WriteLineAsync($"{nameof(DisposeAsync)}: Dirty return of pair {Pair.PairId} started");
                 break;
             case 1:
-                await TestContext.Out.WriteLineAsync($"{nameof(DisposeAsync)}: Pair {Pair.PairId} was properly clean disposed");
+                await _testOut.WriteLineAsync($"{nameof(DisposeAsync)}: Pair {Pair.PairId} was properly clean disposed");
                 return;
             case 2:
                 throw new Exception($"{nameof(DisposeAsync)}: Already dirty disposed pair {Pair.PairId}");

Content.IntegrationTests/PoolTestLogHandler.cs

@@ -0,0 +1,75 @@
+using System;
+using System.IO;
+using NUnit.Framework;
+using Robust.Shared.Log;
+using Robust.Shared.Timing;
+using Serilog.Events;
+
+namespace Content.IntegrationTests;
+
+#nullable enable
+
+/// <summary>
+/// Log handler intended for pooled integration tests.
+/// </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.
+/// </para>
+/// <para>
+/// The active test context can be swapped out so pooled instances can correctly have their logs attributed.
+/// </para>
+/// </remarks>
+public sealed class PoolTestLogHandler : ILogHandler
+{
+    private readonly string? _prefix;
+
+    private RStopwatch _stopwatch;
+
+    public TextWriter? ActiveContext { get; private set; }
+
+    public LogLevel? FailureLevel { get; set; }
+
+    public PoolTestLogHandler(string? prefix)
+    {
+        _prefix = prefix != null ? $"{prefix}: " : "";
+    }
+
+    public void Log(string sawmillName, LogEvent message)
+    {
+        if (ActiveContext is not { } testContext)
+        {
+            // If this gets hit it means something is logging to this instance while it's "between" tests.
+            // This is a bug in either the game or the testing system, and must always be investigated.
+            throw new InvalidOperationException("Log to pool test log handler without active test context");
+        }
+
+        var level = message.Level.ToRobust();
+        var name = LogMessage.LogLevelToName(level);
+        var seconds = _stopwatch.Elapsed.TotalSeconds;
+        var rendered = message.RenderMessage();
+        var line = $"{_prefix}{seconds:F3}s [{name}] {sawmillName}: {rendered}";
+
+        testContext.WriteLine(line);
+
+        if (FailureLevel == null || level < FailureLevel)
+            return;
+
+        testContext.Flush();
+        Assert.Fail($"{line} Exception: {message.Exception}");
+    }
+
+    public void ClearContext()
+    {
+        ActiveContext = null;
+    }
+
+    public void ActivateContext(TextWriter context)
+    {
+        _stopwatch.Restart();
+        ActiveContext = context;
+    }
+}