From 33f388e66ecf4a796145fc4d87a1640bb3455b60 Mon Sep 17 00:00:00 2001 From: Pieter-Jan Briers Date: Sat, 11 Mar 2023 05:09:41 +0100 Subject: [PATCH] Test pooling diagnostic fixes. (#14349) Co-authored-by: metalgearsloth <31366439+metalgearsloth@users.noreply.github.com> Co-authored-by: metalgearsloth --- Content.IntegrationTests/PoolManager.cs | 181 +++++++++++------- .../PoolTestLogHandler.cs | 75 ++++++++ 2 files changed, 192 insertions(+), 64 deletions(-) create mode 100644 Content.IntegrationTests/PoolTestLogHandler.cs diff --git a/Content.IntegrationTests/PoolManager.cs b/Content.IntegrationTests/PoolManager.cs index 695aae7cba..3054be4996 100644 --- a/Content.IntegrationTests/PoolManager.cs +++ b/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; /// 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), - (CCVars.DatabaseSqliteDelay.Name, "0", false), - (CCVars.HolidaysEnabled.Name, "false", false), - (CCVars.GameMap.Name, "Empty", true), - (CCVars.AdminLogsQueueSendDelay.Name, "0", true), - (CCVars.NetPVS.Name, "false", true), - (CCVars.NPCMaxUpdates.Name, "999999", true), - (CCVars.SysWinTickPeriod.Name, "0", true), - (CCVars.ThreadParallelCount.Name, "1", true), - (CCVars.GameRoleTimers.Name, "false", false), - (CCVars.CargoShuttles.Name, "false", false), - (CCVars.EmergencyShuttleEnabled.Name, "false", false), - (CCVars.ProcgenPreload.Name, "false", false), + // @formatter:off + (CCVars.DatabaseSynchronous.Name, "true"), + (CCVars.DatabaseSqliteDelay.Name, "0"), + (CCVars.HolidaysEnabled.Name, "false"), + (CCVars.GameMap.Name, "Empty"), + (CCVars.AdminLogsQueueSendDelay.Name, "0"), + (CVars.NetPVS.Name, "false"), + (CCVars.NPCMaxUpdates.Name, "999999"), + (CVars.ThreadParallelCount.Name, "1"), + (CCVars.GameRoleTimers.Name, "false"), + (CCVars.CargoShuttles.Name, "false"), + (CCVars.EmergencyShuttleEnabled.Name, "false"), + (CCVars.ProcgenPreload.Name, "false"), + // @formatter:on }; private static int PairId; @@ -76,7 +78,9 @@ public static class PoolManager }); } - private static async Task 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().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); } /// @@ -160,7 +169,9 @@ public static class PoolManager } } - private static async Task 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 GetServerClient(PoolSettings poolSettings = null) => await GetServerClientPair(poolSettings ?? new PoolSettings()); - private static string GetDefaultTestName() + private static string GetDefaultTestName(TestContext testContext) { - return TestContext.CurrentContext.Test.FullName - .Replace("Content.IntegrationTests.Tests.", ""); + return testContext.Test.FullName.Replace("Content.IntegrationTests.Tests.", ""); } private static async Task 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 CleanPooledPair(poolSettings, pair); + await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Cleaning existing pair"); + await CleanPooledPair(poolSettings, pair, testOut); } } else { - await TestContext.Out.WriteLineAsync($"{nameof(GetServerClientPair)}: Creating a new pair, no suitable pair found in pool"); - pair = await CreateServerClientPair(poolSettings); + await testOut.WriteLineAsync($"{nameof(GetServerClientPair)}: Creating a new pair, no suitable pair found in pool"); + 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(); await pair.Server.WaitPost(() => { @@ -383,7 +404,7 @@ public static class PoolManager var cNetMgr = pair.Client.ResolveDependency(); 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(); @@ -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().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 CreateServerClientPair(PoolSettings poolSettings) + private static async Task CreateServerClientPair(PoolSettings poolSettings, TextWriter testOut) { Pair pair; try { - var client = await GenerateClient(poolSettings); - var server = await GenerateServer(poolSettings); - pair = new Pair { Server = server, Client = client, PairId = Interlocked.Increment(ref PairId) }; + var (client, clientLog) = await GenerateClient(poolSettings, testOut); + var (server, serverLog) = await GenerateServer(poolSettings, testOut); + 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); + } } /// @@ -793,24 +836,32 @@ public sealed class Pair /// 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(); - 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(); - 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}"); diff --git a/Content.IntegrationTests/PoolTestLogHandler.cs b/Content.IntegrationTests/PoolTestLogHandler.cs new file mode 100644 index 0000000000..2dcb40c603 --- /dev/null +++ b/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 + +/// +/// Log handler intended for pooled integration tests. +/// +/// +/// +/// This class logs to two places: an NUnit +/// (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. +/// +/// +/// The active test context can be swapped out so pooled instances can correctly have their logs attributed. +/// +/// +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; + } +} -- 2.52.0