attempt at resolving game interface threading issues (maybe)

Application/Misc/ScriptPlugin.cs

@@ -113,7 +113,8 @@ namespace IW4MAdmin.Application.Misc
                 }
 
                 _scriptEngine = new Engine(cfg =>
-                    cfg.AddExtensionMethods(typeof(Utilities), typeof(Enumerable), typeof(Queryable), typeof(ScriptPluginExtensions))
+                    cfg.AddExtensionMethods(typeof(Utilities), typeof(Enumerable), typeof(Queryable),
+                            typeof(ScriptPluginExtensions))
                         .AllowClr(new[]
                         {
                             typeof(System.Net.Http.HttpClient).Assembly,
@@ -360,7 +361,7 @@ namespace IW4MAdmin.Application.Misc
                 }
             }
         }
-        
+
         public T WrapDelegate<T>(Delegate act, params object[] args)
         {
             try
@@ -401,6 +402,7 @@ namespace IW4MAdmin.Application.Misc
                 {
                     dynamicCommand.permission = perm.ToString();
                 }
+
                 string permission = dynamicCommand.permission;
                 List<Server.Game> supportedGames = null;
                 var targetRequired = false;
@@ -502,10 +504,14 @@ namespace IW4MAdmin.Application.Misc
 
         private void BeginGetDvar(Server server, string dvarName, Delegate onCompleted)
         {
+            var operationTimeout = TimeSpan.FromSeconds(5);
+
             void OnComplete(IAsyncResult result)
             {
                 try
                 {
+                    _onProcessing.Wait();
+
                     var (success, value) = (ValueTuple<bool, string>)result.AsyncState;
                     onCompleted.DynamicInvoke(JsValue.Undefined,
                         new[]
@@ -520,7 +526,7 @@ namespace IW4MAdmin.Application.Misc
                 {
                     using (LogContext.PushProperty("Server", server.ToString()))
                     {
-                        _logger.LogError(ex, "Could not complete BeginGetDvar for {Filename} {@Location}",
+                        _logger.LogError(ex, "Could not invoke BeginGetDvar callback for {Filename} {@Location}",
                             Path.GetFileName(_fileName), ex.Location);
                     }
                 }
@@ -528,41 +534,51 @@ namespace IW4MAdmin.Application.Misc
                 {
                     _logger.LogError(ex, "Could not complete {BeginGetDvar} for {Class}", nameof(BeginGetDvar), Name);
                 }
-            }
-
-            var tokenSource = new CancellationTokenSource();
-            tokenSource.CancelAfter(TimeSpan.FromSeconds(5));
-            
-            server.BeginGetDvar(dvarName, result =>
-            {
-                var shouldRelease = false;
-                try
-                {
-                    _onProcessing.Wait(tokenSource.Token);
-                    shouldRelease = true;
-                }
-
                 finally
                 {
-                    OnComplete(result);
+                    if (_onProcessing.CurrentCount == 0)
-
-                    if (_onProcessing.CurrentCount == 0 && shouldRelease)
                     {
-                        _onProcessing.Release();
+                        _onProcessing.Release(1);
                     }
                 }
-            }, tokenSource.Token);
+            }
+
+            new Thread(() =>
+            {
+                var tokenSource = new CancellationTokenSource();
+                tokenSource.CancelAfter(operationTimeout);
+
+                server.GetDvarAsync<string>(dvarName, token: tokenSource.Token).ContinueWith(action =>
+                {
+                    if (action.IsCompletedSuccessfully)
+                    {
+                        OnComplete(new AsyncResult
+                        {
+                            IsCompleted = true,
+                            AsyncState = (true, action.Result.Value)
+                        });
+                    }
+                    else
+                    {
+                        OnComplete(new AsyncResult
+                        {
+                            IsCompleted = false,
+                            AsyncState = (false, (string)null)
+                        });
+                    }
+                });
+            }).Start();
         }
 
         private void BeginSetDvar(Server server, string dvarName, string dvarValue, Delegate onCompleted)
         {
-            var tokenSource = new CancellationTokenSource();
+            var operationTimeout = TimeSpan.FromSeconds(5);
-            tokenSource.CancelAfter(TimeSpan.FromSeconds(5));
+
-            
             void OnComplete(IAsyncResult result)
             {
                 try
                 {
+                    _onProcessing.Wait();
                     var success = (bool)result.AsyncState;
                     onCompleted.DynamicInvoke(JsValue.Undefined,
                         new[]
@@ -585,25 +601,40 @@ namespace IW4MAdmin.Application.Misc
                 {
                     _logger.LogError(ex, "Could not complete {BeginSetDvar} for {Class}", nameof(BeginSetDvar), Name);
                 }
-            }
-            
-            server.BeginSetDvar(dvarName, dvarValue, result =>
-            {
-                var shouldRelease = false;
-                try
-                {
-                    _onProcessing.Wait(tokenSource.Token);
-                    shouldRelease = true;
-                }
                 finally
                 {
-                    OnComplete(result);
+                    if (_onProcessing.CurrentCount == 0)
-                    if (_onProcessing.CurrentCount == 0 && shouldRelease)
                     {
-                        _onProcessing.Release();
+                        _onProcessing.Release(1);
                     }
                 }
-            }, tokenSource.Token);
+            }
+
+            new Thread(() =>
+            {
+                var tokenSource = new CancellationTokenSource();
+                tokenSource.CancelAfter(operationTimeout);
+
+                server.SetDvarAsync(dvarName, dvarValue, token: tokenSource.Token).ContinueWith(action =>
+                {
+                    if (action.IsCompletedSuccessfully)
+                    {
+                        OnComplete(new AsyncResult
+                        {
+                            IsCompleted = true,
+                            AsyncState = true
+                        });
+                    }
+                    else
+                    {
+                        OnComplete(new AsyncResult
+                        {
+                            IsCompleted = false,
+                            AsyncState = false
+                        });
+                    }
+                });
+            }).Start();
         }
     }
 
@@ -617,7 +648,6 @@ namespace IW4MAdmin.Application.Misc
                 return true;
             }
 
-
             result = JsValue.Null;
             return false;
         }

Application/Misc/ScriptPluginTimerHelper.cs

@@ -17,7 +17,7 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper
     private const int DefaultDelay = 0;
     private const int DefaultInterval = 1000;
     private readonly ILogger _logger;
-    private readonly ManualResetEventSlim _onRunningTick = new();
+    private readonly SemaphoreSlim _onRunningTick = new(1, 1);
     private SemaphoreSlim _onDependentAction;
 
     public ScriptPluginTimerHelper(ILogger<ScriptPluginTimerHelper> logger)
@@ -31,6 +31,7 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper
         {
             Stop();
         }
+
         _onRunningTick.Dispose();
     }
 
@@ -50,12 +51,11 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper
         {
             throw new ArgumentException("Timer interval must be at least 20ms");
         }
-        
+
         Stop();
-        
+
         _logger.LogDebug("Starting script timer...");
 
-        _onRunningTick.Set();
         _timer ??= new Timer(callback => _actions(), null, delay, interval);
         IsRunning = true;
     }
@@ -76,7 +76,7 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper
         {
             return;
         }
-        
+
         _logger.LogDebug("Stopping script timer...");
         _timer.Change(Timeout.Infinite, Timeout.Infinite);
         _timer.Dispose();
@@ -100,54 +100,79 @@ public class ScriptPluginTimerHelper : IScriptPluginTimerHelper
 
         _jsAction = action;
         _actionName = actionName;
-        _actions = OnTick;
+        _actions = OnTickInternal;
     }
 
     private void ReleaseThreads()
     {
-        _onRunningTick.Set();
+        _logger.LogDebug("-Releasing OnTick for timer");
+
+        if (_onRunningTick.CurrentCount == 0)
+        {
+            _onRunningTick.Release(1);
+        }
 
         if (_onDependentAction?.CurrentCount != 0)
         {
             return;
         }
-        _logger.LogDebug("-Releasing OnTick for timer");
+
         _onDependentAction?.Release(1);
     }
-    private void OnTick()
+
+    private async void OnTickInternal()
     {
+        var previousTimerRunning = false;
         try
         {
-            if (!_onRunningTick.IsSet)
+            if (_onRunningTick.CurrentCount == 0)
             {
                 _logger.LogDebug("Previous {OnTick} is still running, so we are skipping this one",
-                    nameof(OnTick));
+                    nameof(OnTickInternal));
+                previousTimerRunning = true;
                 return;
             }
 
-            _onRunningTick.Reset();
+            await _onRunningTick.WaitAsync();
 
-            // the js engine is not thread safe so we need to ensure we're not executing OnTick and OnEventAsync simultaneously
+            var tokenSource = new CancellationTokenSource();
-            _onDependentAction?.Wait();
+            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);
+                }
+            }
+            catch (OperationCanceledException)
+            {
+                _logger.LogDebug("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 });
             _logger.LogDebug("OnTick took {Time}ms", (DateTime.Now - start).TotalMilliseconds);
-            ReleaseThreads();
         }
-
+        catch (Exception ex) when (ex.InnerException is JavaScriptException jsx)
-        catch (Exception ex) when (ex.InnerException is JavaScriptException jsex)
         {
-            _logger.LogError(jsex,
+            _logger.LogError(jsx,
                 "Could not execute timer tick for script action {ActionName} [@{LocationInfo}]", _actionName,
-                jsex.Location);
+                jsx.Location);
-            ReleaseThreads();
         }
         catch (Exception ex)
         {
             _logger.LogError(ex, "Could not execute timer tick for script action {ActionName}", _actionName);
-            _onRunningTick.Set();
+        }
-            ReleaseThreads();
+        finally
+        {
+            if (!previousTimerRunning)
+            {
+                ReleaseThreads();
+            }
         }
     }