From f4e7d5daf990f3735458a88e038c4132e0c33568 Mon Sep 17 00:00:00 2001 From: RaidMax Date: Sun, 23 Oct 2022 14:03:33 -0500 Subject: [PATCH] harden up the script timer/game interface dvar operations for multithreading --- Application/IW4MServer.cs | 8 ++- Application/Misc/ScriptPlugin.cs | 47 +++++++++++++++- Application/Misc/ScriptPluginTimerHelper.cs | 61 +++++++++++++-------- SharedLibraryCore/Server.cs | 19 +------ SharedLibraryCore/Utilities.cs | 8 +-- 5 files changed, 95 insertions(+), 48 deletions(-) diff --git a/Application/IW4MServer.cs b/Application/IW4MServer.cs index 1d393cd56..7e2265336 100644 --- a/Application/IW4MServer.cs +++ b/Application/IW4MServer.cs @@ -867,6 +867,12 @@ namespace IW4MAdmin /// async Task[]> PollPlayersAsync(CancellationToken token) { + if (DateTime.Now - (MatchEndTime ?? MatchStartTime) < TimeSpan.FromSeconds(15)) + { + ServerLogger.LogDebug("Skipping status poll attempt because the match ended recently"); + return null; + } + var currentClients = GetClientsAsList(); var statusResponse = await this.GetStatusAsync(token); @@ -874,7 +880,7 @@ namespace IW4MAdmin { return null; } - + var polledClients = statusResponse.Clients.AsEnumerable(); if (Manager.GetApplicationSettings().Configuration().IgnoreBots) diff --git a/Application/Misc/ScriptPlugin.cs b/Application/Misc/ScriptPlugin.cs index b78f275b1..5e52e5ffb 100644 --- a/Application/Misc/ScriptPlugin.cs +++ b/Application/Misc/ScriptPlugin.cs @@ -10,6 +10,7 @@ using SharedLibraryCore.Interfaces; using System.Collections.Generic; using System.IO; using System.Linq; +using System.Reflection; using System.Text; using System.Threading; using System.Threading.Tasks; @@ -353,6 +354,13 @@ namespace IW4MAdmin.Application.Misc var result = action.DynamicInvoke(JsValue.Undefined, args); return (T)(result as JsValue)?.ToObject(); } + catch (TargetInvocationException ex) when (ex.InnerException is JavaScriptException jsEx) + { + _logger.LogError(ex, + "Encountered JavaScript runtime error while executing {MethodName} for script plugin {Plugin} with event type {@LocationInfo} {StackTrace}", + nameof(ExecuteAction), Path.GetFileName(_fileName), jsEx.Location, jsEx.JavaScriptStackTrace); + throw; + } finally { if (_onProcessing.CurrentCount == 0) @@ -370,6 +378,13 @@ namespace IW4MAdmin.Application.Misc return (T)(act.DynamicInvoke(JsValue.Null, args.Select(arg => JsValue.FromObject(_scriptEngine, arg)).ToArray()) as ObjectWrapper)?.ToObject(); } + catch (TargetInvocationException ex) when (ex.InnerException is JavaScriptException jsEx) + { + _logger.LogError(ex, + "Encountered JavaScript runtime error while executing {MethodName} for script plugin {Plugin} with event type {@LocationInfo} {StackTrace}", + nameof(WrapDelegate), Path.GetFileName(_fileName), jsEx.Location, jsEx.JavaScriptStackTrace); + throw; + } finally { if (_onProcessing.CurrentCount == 0) @@ -545,7 +560,21 @@ namespace IW4MAdmin.Application.Misc new Thread(() => { - var tokenSource = new CancellationTokenSource(); + if (DateTime.Now - (server.MatchEndTime ?? server.MatchStartTime) < TimeSpan.FromSeconds(15)) + { + using (LogContext.PushProperty("Server", server.ToString())) + { + _logger.LogDebug("Not getting DVar because match recently ended"); + } + + OnComplete(new AsyncResult + { + IsCompleted = false, + AsyncState = (false, (string)null) + }); + } + + using var tokenSource = new CancellationTokenSource(); tokenSource.CancelAfter(operationTimeout); server.GetDvarAsync(dvarName, token: tokenSource.Token).ContinueWith(action => @@ -612,7 +641,21 @@ namespace IW4MAdmin.Application.Misc new Thread(() => { - var tokenSource = new CancellationTokenSource(); + if (DateTime.Now - (server.MatchEndTime ?? server.MatchStartTime) < TimeSpan.FromSeconds(15)) + { + using (LogContext.PushProperty("Server", server.ToString())) + { + _logger.LogDebug("Not setting DVar because match recently ended"); + } + + OnComplete(new AsyncResult + { + IsCompleted = false, + AsyncState = false + }); + } + + using var tokenSource = new CancellationTokenSource(); tokenSource.CancelAfter(operationTimeout); server.SetDvarAsync(dvarName, dvarValue, token: tokenSource.Token).ContinueWith(action => diff --git a/Application/Misc/ScriptPluginTimerHelper.cs b/Application/Misc/ScriptPluginTimerHelper.cs index 43d790503..116885b6d 100644 --- a/Application/Misc/ScriptPluginTimerHelper.cs +++ b/Application/Misc/ScriptPluginTimerHelper.cs @@ -14,8 +14,11 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper private Action _actions; private Delegate _jsAction; private string _actionName; + private int _interval = DefaultInterval; + private long _waitingCount; private const int DefaultDelay = 0; private const int DefaultInterval = 1000; + private const int MaxWaiting = 10; private readonly ILogger _logger; private readonly SemaphoreSlim _onRunningTick = new(1, 1); private SemaphoreSlim _onDependentAction; @@ -57,6 +60,7 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper _logger.LogDebug("Starting script timer..."); _timer ??= new Timer(callback => _actions(), null, delay, interval); + _interval = interval; IsRunning = true; } @@ -103,55 +107,67 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper _actions = OnTickInternal; } - private void ReleaseThreads() + private void ReleaseThreads(bool releaseOnRunning, bool releaseOnDependent) { - _logger.LogDebug("-Releasing OnTick for timer"); - - if (_onRunningTick.CurrentCount == 0) + if (releaseOnRunning && _onRunningTick.CurrentCount == 0) { + _logger.LogDebug("-Releasing OnRunning for timer"); _onRunningTick.Release(1); } - if (_onDependentAction?.CurrentCount != 0) + if (releaseOnDependent && _onDependentAction?.CurrentCount == 0) { - return; + _onDependentAction?.Release(1); } - - _onDependentAction?.Release(1); } private async void OnTickInternal() { - var previousTimerRunning = false; + var releaseOnRunning = false; + var releaseOnDependent = false; + try { - if (_onRunningTick.CurrentCount == 0) + try + { + if (Interlocked.Read(ref _waitingCount) > MaxWaiting) + { + _logger.LogWarning("Reached max number of waiting count ({WaitingCount}) for {OnTick}", + _waitingCount, nameof(OnTickInternal)); + return; + } + + Interlocked.Increment(ref _waitingCount); + using var tokenSource1 = new CancellationTokenSource(); + tokenSource1.CancelAfter(TimeSpan.FromMilliseconds(_interval)); + await _onRunningTick.WaitAsync(tokenSource1.Token); + releaseOnRunning = true; + } + catch (OperationCanceledException) { _logger.LogDebug("Previous {OnTick} is still running, so we are skipping this one", nameof(OnTickInternal)); - previousTimerRunning = true; return; } - await _onRunningTick.WaitAsync(); - - var tokenSource = new CancellationTokenSource(); + using var tokenSource = new CancellationTokenSource(); tokenSource.CancelAfter(TimeSpan.FromSeconds(5)); - + try { // the js engine is not thread safe so we need to ensure we're not executing OnTick and OnEventAsync simultaneously if (_onDependentAction is not null) { await _onDependentAction.WaitAsync(tokenSource.Token); + releaseOnDependent = true; } } catch (OperationCanceledException) { - _logger.LogDebug("Dependent action did not release in allotted time so we are cancelling this tick"); + _logger.LogWarning("Dependent action did not release in allotted time so we are cancelling this tick"); return; } - + _logger.LogDebug("+Running OnTick for timer"); var start = DateTime.Now; _jsAction.DynamicInvoke(JsValue.Undefined, new[] { JsValue.Undefined }); @@ -160,8 +176,9 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper catch (Exception ex) when (ex.InnerException is JavaScriptException jsx) { _logger.LogError(jsx, - "Could not execute timer tick for script action {ActionName} [@{LocationInfo}]", _actionName, - jsx.Location); + "Could not execute timer tick for script action {ActionName} [{@LocationInfo}] [{@StackTrace}]", + _actionName, + jsx.Location, jsx.JavaScriptStackTrace); } catch (Exception ex) { @@ -169,10 +186,8 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper } finally { - if (!previousTimerRunning) - { - ReleaseThreads(); - } + ReleaseThreads(releaseOnRunning, releaseOnDependent); + Interlocked.Decrement(ref _waitingCount); } } diff --git a/SharedLibraryCore/Server.cs b/SharedLibraryCore/Server.cs index 943860bd8..67b9ba69e 100644 --- a/SharedLibraryCore/Server.cs +++ b/SharedLibraryCore/Server.cs @@ -409,24 +409,9 @@ namespace SharedLibraryCore public abstract Task GetIdForServer(Server server = null); - public string[] ExecuteServerCommand(string command, int timeoutMs = 1000) - { - var tokenSource = new CancellationTokenSource(); - tokenSource.CancelAfter(TimeSpan.FromSeconds(timeoutMs)); - - try - { - return this.ExecuteCommandAsync(command, tokenSource.Token).GetAwaiter().GetResult(); - } - catch - { - return null; - } - } - public string GetServerDvar(string dvarName, int timeoutMs = 1000) { - var tokenSource = new CancellationTokenSource(); + using var tokenSource = new CancellationTokenSource(); tokenSource.CancelAfter(TimeSpan.FromSeconds(timeoutMs)); try { @@ -440,7 +425,7 @@ namespace SharedLibraryCore public bool SetServerDvar(string dvarName, string dvarValue, int timeoutMs = 1000) { - var tokenSource = new CancellationTokenSource(); + using var tokenSource = new CancellationTokenSource(); tokenSource.CancelAfter(TimeSpan.FromSeconds(timeoutMs)); try { diff --git a/SharedLibraryCore/Utilities.cs b/SharedLibraryCore/Utilities.cs index 56024160a..b76bb1807 100644 --- a/SharedLibraryCore/Utilities.cs +++ b/SharedLibraryCore/Utilities.cs @@ -18,7 +18,6 @@ using Microsoft.Extensions.Logging; using SharedLibraryCore.Configuration; using SharedLibraryCore.Database.Models; using SharedLibraryCore.Dtos.Meta; -using SharedLibraryCore.Formatting; using SharedLibraryCore.Helpers; using SharedLibraryCore.Interfaces; using SharedLibraryCore.Localization; @@ -1003,9 +1002,9 @@ namespace SharedLibraryCore return true; } - catch (Exception e) + catch (Exception ex) { - logger.LogError(e, $"Could not create penalty of type {penalty.Type.ToString()}"); + logger.LogError(ex, "Could not create penalty of type {PenaltyType}", penalty.Type.ToString()); } return false; @@ -1052,8 +1051,7 @@ namespace SharedLibraryCore { await Task.WhenAny(task, Task.Delay(timeout)); } - - + public static bool ShouldHideLevel(this Permission perm) { return perm == Permission.Flagged;