From e8dfdab4501ae1098e93ffa891fcb8b81361419d Mon Sep 17 00:00:00 2001 From: Jordan Dominion Date: Tue, 9 Jan 2024 08:34:08 -0500 Subject: [PATCH 1/6] Better handle database connection cancellation errors --- tests/Tgstation.Server.Tests/Live/HardFailLogger.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/Tgstation.Server.Tests/Live/HardFailLogger.cs b/tests/Tgstation.Server.Tests/Live/HardFailLogger.cs index 2fc1d32da0..ffef40cdbe 100644 --- a/tests/Tgstation.Server.Tests/Live/HardFailLogger.cs +++ b/tests/Tgstation.Server.Tests/Live/HardFailLogger.cs @@ -27,7 +27,7 @@ namespace Tgstation.Server.Tests.Live && !((exception is BadHttpRequestException) && logMessage.Contains("Unexpected end of request content.")) // canceled request && !logMessage.StartsWith("Error disconnecting connection ") && !(logMessage.StartsWith("An exception occurred while iterating over the results of a query for context type") && (exception is OperationCanceledException || exception?.InnerException is OperationCanceledException)) - && !(logMessage.StartsWith("An error occurred using the connection to database ") && (exception is OperationCanceledException || exception?.InnerException is OperationCanceledException)) + && !(logMessage.Contains("An error occurred using the connection to database ") && (exception == null || (exception is OperationCanceledException || exception?.InnerException is OperationCanceledException))) && !(logMessage.StartsWith("Error when dispatching 'OnConnectedAsync' on hub") && (exception is OperationCanceledException || exception?.InnerException is OperationCanceledException)) && !(logMessage.StartsWith("An exception occurred in the database while saving changes for context type") && (exception is OperationCanceledException || exception?.InnerException is OperationCanceledException))) || (logLevel == LogLevel.Critical && logMessage != "DropDatabase configuration option set! Dropping any existing database...")) From f4d94d02847749819781aaea14bd115e1b644e7b Mon Sep 17 00:00:00 2001 From: Jordan Dominion Date: Tue, 9 Jan 2024 17:21:09 -0500 Subject: [PATCH 2/6] Update nuget packages Closes #1767 Closes #1766 --- build/TestCommon.props | 2 +- .../Tgstation.Server.Api.csproj | 2 +- .../Tgstation.Server.Client.csproj | 4 ++-- .../Tgstation.Server.Host.csproj | 18 +++++++++--------- .../Tgstation.Server.Host.Tests.csproj | 2 +- 5 files changed, 14 insertions(+), 14 deletions(-) diff --git a/build/TestCommon.props b/build/TestCommon.props index b68ecb3415..c533dded96 100644 --- a/build/TestCommon.props +++ b/build/TestCommon.props @@ -16,7 +16,7 @@ - + diff --git a/src/Tgstation.Server.Api/Tgstation.Server.Api.csproj b/src/Tgstation.Server.Api/Tgstation.Server.Api.csproj index e499846add..1c5c6e8c65 100644 --- a/src/Tgstation.Server.Api/Tgstation.Server.Api.csproj +++ b/src/Tgstation.Server.Api/Tgstation.Server.Api.csproj @@ -27,7 +27,7 @@ - + diff --git a/src/Tgstation.Server.Client/Tgstation.Server.Client.csproj b/src/Tgstation.Server.Client/Tgstation.Server.Client.csproj index 876f1097d6..62e15714d5 100644 --- a/src/Tgstation.Server.Client/Tgstation.Server.Client.csproj +++ b/src/Tgstation.Server.Client/Tgstation.Server.Client.csproj @@ -11,9 +11,9 @@ - + - + diff --git a/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj b/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj index 733400da3d..41a711c7d6 100644 --- a/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj +++ b/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj @@ -76,21 +76,21 @@ - + - + - + - + - + runtime; build; native; contentfiles; analyzers; buildtransitive - + - + @@ -98,7 +98,7 @@ - + @@ -120,7 +120,7 @@ - + diff --git a/tests/Tgstation.Server.Host.Tests/Tgstation.Server.Host.Tests.csproj b/tests/Tgstation.Server.Host.Tests/Tgstation.Server.Host.Tests.csproj index 331d95e564..d6f3aa8e39 100644 --- a/tests/Tgstation.Server.Host.Tests/Tgstation.Server.Host.Tests.csproj +++ b/tests/Tgstation.Server.Host.Tests/Tgstation.Server.Host.Tests.csproj @@ -6,7 +6,7 @@ - + From 5e5987c3651e55399b603175e1e6ddeb392b3a2f Mon Sep 17 00:00:00 2001 From: Jordan Dominion Date: Tue, 9 Jan 2024 17:24:23 -0500 Subject: [PATCH 3/6] Remove unused `System.IdentityModel.Tokens.Jwt` package --- src/Tgstation.Server.Host/Tgstation.Server.Host.csproj | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj b/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj index 41a711c7d6..e6a0a19d97 100644 --- a/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj +++ b/src/Tgstation.Server.Host/Tgstation.Server.Host.csproj @@ -119,8 +119,6 @@ - - From e377a2ed9871d623bcf412dcded0effbd8538f05 Mon Sep 17 00:00:00 2001 From: Jordan Dominion Date: Tue, 9 Jan 2024 18:44:48 -0500 Subject: [PATCH 4/6] Clean up race condition in BridgeController content logging disabling --- .../Controllers/BridgeController.cs | 19 +++++++++++++------ .../Live/Instance/WatchdogTest.cs | 4 ++-- 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/src/Tgstation.Server.Host/Controllers/BridgeController.cs b/src/Tgstation.Server.Host/Controllers/BridgeController.cs index 4b1a1fac3e..f7711a7833 100644 --- a/src/Tgstation.Server.Host/Controllers/BridgeController.cs +++ b/src/Tgstation.Server.Host/Controllers/BridgeController.cs @@ -36,7 +36,12 @@ namespace Tgstation.Server.Host.Controllers /// /// If the content of bridge requests and responses should be logged. /// - internal static bool LogContent { get; set; } + static bool LogContent => logContentDisableCounter == 0; + + /// + /// Counter which, if not zero, indicates content logging should be disabled. + /// + static uint logContentDisableCounter; /// /// Static counter for the number of requests processed. @@ -54,12 +59,14 @@ namespace Tgstation.Server.Host.Controllers readonly ILogger logger; /// - /// Initializes static members of the class. + /// Temporarily disable content logging. Must be followed up with a call to . /// - static BridgeController() - { - LogContent = true; - } + internal static void TemporarilyDisableContentLogging() => Interlocked.Increment(ref logContentDisableCounter); + + /// + /// Reenable content logging. Must be preceeded with a call to . + /// + internal static void ReenableContentLogging() => Interlocked.Decrement(ref logContentDisableCounter); /// /// Initializes a new instance of the class. diff --git a/tests/Tgstation.Server.Tests/Live/Instance/WatchdogTest.cs b/tests/Tgstation.Server.Tests/Live/Instance/WatchdogTest.cs index ceb8e80fe7..4d5e1685a5 100644 --- a/tests/Tgstation.Server.Tests/Live/Instance/WatchdogTest.cs +++ b/tests/Tgstation.Server.Tests/Live/Instance/WatchdogTest.cs @@ -893,7 +893,7 @@ namespace Tgstation.Server.Tests.Live.Instance { // first check the bridge limits var bridgeTestsTcs = new TaskCompletionSource(); - BridgeController.LogContent = false; + BridgeController.TemporarilyDisableContentLogging(); using (var loggerFactory = LoggerFactory.Create(builder => { builder.AddConsole(); @@ -914,7 +914,7 @@ namespace Tgstation.Server.Tests.Live.Instance await bridgeTestsTcs.Task.WaitAsync(cancellationToken); } - BridgeController.LogContent = true; + BridgeController.ReenableContentLogging(); // Time for DD to revert the bridge access identifier change await Task.Delay(TimeSpan.FromSeconds(1), cancellationToken); From 74a04ede7317bef67bde1beabf499ba14c47543d Mon Sep 17 00:00:00 2001 From: Jordan Dominion Date: Tue, 9 Jan 2024 18:50:13 -0500 Subject: [PATCH 5/6] Add a bunch more bridge request logging --- .../Components/InstanceManager.cs | 9 +++++++ .../Controllers/BridgeController.cs | 24 ++++++++++++------- 2 files changed, 25 insertions(+), 8 deletions(-) diff --git a/src/Tgstation.Server.Host/Components/InstanceManager.cs b/src/Tgstation.Server.Host/Components/InstanceManager.cs index 8c97f5c74d..c86f5c8ede 100644 --- a/src/Tgstation.Server.Host/Components/InstanceManager.cs +++ b/src/Tgstation.Server.Host/Components/InstanceManager.cs @@ -518,6 +518,7 @@ namespace Tgstation.Server.Host.Components } IBridgeHandler? bridgeHandler = null; + var loggedDelay = false; for (var i = 0; bridgeHandler == null && i < 30; ++i) { // There's a miniscule time period where we could potentially receive a bridge request and not have the registration ready when we launch DD @@ -525,7 +526,15 @@ namespace Tgstation.Server.Host.Components Task delayTask = Task.CompletedTask; lock (bridgeHandlers) if (!bridgeHandlers.TryGetValue(accessIdentifier, out bridgeHandler)) + { + if (!loggedDelay) + { + logger.LogTrace("Received bridge request with unregistered access identifier \"{aid}\". Waiting up to 3 seconds for it to be registered...", accessIdentifier); + loggedDelay = true; + } + delayTask = asyncDelayer.Delay(TimeSpan.FromMilliseconds(100), cancellationToken); + } await delayTask; } diff --git a/src/Tgstation.Server.Host/Controllers/BridgeController.cs b/src/Tgstation.Server.Host/Controllers/BridgeController.cs index f7711a7833..10f9ae94af 100644 --- a/src/Tgstation.Server.Host/Controllers/BridgeController.cs +++ b/src/Tgstation.Server.Host/Controllers/BridgeController.cs @@ -94,16 +94,16 @@ namespace Tgstation.Server.Host.Controllers [AllowAnonymous] public async ValueTask Process([FromQuery] string data, CancellationToken cancellationToken) { - // Nothing to see here - var remoteIP = Request.HttpContext.Connection.RemoteIpAddress; - if (remoteIP == null || !IPAddress.IsLoopback(remoteIP)) - { - logger.LogTrace("Rejecting remote bridge request from {remoteIP}", remoteIP); - return Forbid(); - } - using (LogContext.PushProperty(SerilogContextHelper.BridgeRequestIterationContextProperty, Interlocked.Increment(ref requestsProcessed))) { + // Nothing to see here + var remoteIP = Request.HttpContext.Connection.RemoteIpAddress; + if (remoteIP == null || !IPAddress.IsLoopback(remoteIP)) + { + logger.LogTrace("Rejecting remote bridge request from {remoteIP}", remoteIP); + return Forbid(); + } + BridgeParameters? request; try { @@ -113,6 +113,9 @@ namespace Tgstation.Server.Host.Controllers { if (LogContent) logger.LogWarning(ex, "Error deserializing bridge request: {badJson}", data); + else + logger.LogWarning(ex, "Error deserializing bridge request!"); + return BadRequest(); } @@ -120,11 +123,16 @@ namespace Tgstation.Server.Host.Controllers { if (LogContent) logger.LogWarning("Error deserializing bridge request: {badJson}", data); + else + logger.LogWarning("Error deserializing bridge request!"); + return BadRequest(); } if (LogContent) logger.LogTrace("Bridge Request: {json}", data); + else + logger.LogTrace("Bridge Request"); var response = await bridgeDispatcher.ProcessBridgeRequest(request, cancellationToken); if (response == null) From a59a67d0e4d87ff86fb8ea65d0c9449bec40d819 Mon Sep 17 00:00:00 2001 From: Jordan Dominion Date: Tue, 9 Jan 2024 21:52:30 -0500 Subject: [PATCH 6/6] Properly dispose test TCP listeners --- .../Live/TestLiveServer.cs | 22 ++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/tests/Tgstation.Server.Tests/Live/TestLiveServer.cs b/tests/Tgstation.Server.Tests/Live/TestLiveServer.cs index 0a4b956cc8..91466db1d0 100644 --- a/tests/Tgstation.Server.Tests/Live/TestLiveServer.cs +++ b/tests/Tgstation.Server.Tests/Live/TestLiveServer.cs @@ -61,6 +61,16 @@ namespace Tgstation.Server.Tests.Live static readonly Lazy mainDDPort = new(() => FreeTcpPort(odDDPort.Value, odDMPort.Value, compatDMPort.Value, compatDDPort.Value)); static readonly Lazy mainDMPort = new(() => FreeTcpPort(odDDPort.Value, odDMPort.Value, compatDMPort.Value, compatDDPort.Value, mainDDPort.Value)); + static void InitializePorts() + { + _ = odDMPort.Value; + _ = odDDPort.Value; + _ = compatDMPort.Value; + _ = compatDDPort.Value; + _ = mainDDPort.Value; + _ = mainDMPort.Value; + } + readonly ServerClientFactory clientFactory = new (new ProductHeaderValue(Assembly.GetExecutingAssembly().GetName().Name, Assembly.GetExecutingAssembly().GetName().Version.ToString())); public static List GetEngineServerProcessesOnPort(EngineType engineType, ushort? port) @@ -162,7 +172,8 @@ namespace Tgstation.Server.Tests.Live } catch { - l.Stop(); + using (l) + l.Stop(); throw; } @@ -172,10 +183,9 @@ namespace Tgstation.Server.Tests.Live } finally { - foreach(var l in listeners) - { - l.Stop(); - } + foreach (var l in listeners) + using (l) + l.Stop(); } Console.WriteLine($"Allocated port: {result}"); @@ -1238,6 +1248,8 @@ namespace Tgstation.Server.Tests.Live using (var currentProcess = System.Diagnostics.Process.GetCurrentProcess()) Assert.AreEqual(ProcessPriorityClass.Normal, currentProcess.PriorityClass); + InitializePorts(); + var maximumTestMinutes = TestingUtils.RunningInGitHubActions ? 90 : 20; using var hardCancellationTokenSource = new CancellationTokenSource(TimeSpan.FromMinutes(maximumTestMinutes)); var hardCancellationToken = hardCancellationTokenSource.Token;