harden up the script timer/game interface dvar operations for multithreading

Application/IW4MServer.cs

@@ -867,6 +867,12 @@ namespace IW4MAdmin
         /// <returns></returns>
         async Task<List<EFClient>[]> 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)

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<string>(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 =>

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 (releaseOnRunning && _onRunningTick.CurrentCount == 0)
-
-        if (_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();
+            using var tokenSource = new CancellationTokenSource();
-
-            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,
+                "Could not execute timer tick for script action {ActionName} [{@LocationInfo}] [{@StackTrace}]",
-                jsx.Location);
+                _actionName,
+                jsx.Location, jsx.JavaScriptStackTrace);
         }
         catch (Exception ex)
         {
@@ -169,10 +186,8 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper
         }
         finally
         {
-            if (!previousTimerRunning)
+            ReleaseThreads(releaseOnRunning, releaseOnDependent);
-            {
+            Interlocked.Decrement(ref _waitingCount);
-                ReleaseThreads();
-            }
         }
     }
 

SharedLibraryCore/Server.cs

@@ -409,24 +409,9 @@ namespace SharedLibraryCore
 
         public abstract Task<long> 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
             {

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;