fix alias command sending message to origin instead of target

(hopefully) fix an issue with banned players causing exception if they create events before they are kicked out
fix issues with sometimes wrong error message for timeout
show most recent IP address at top of alias list
optimization to some sql queries

Application/ApplicationManager.cs

@@ -33,8 +33,6 @@ namespace IW4MAdmin.Application
         public ILogger Logger => GetLogger(0);
         public bool Running { get; private set; }
         public bool IsInitialized { get; private set; }
-        // expose the event handler so we can execute the events
-        public OnServerEventEventHandler OnServerEvent { get; set; }
         public DateTime StartTime { get; private set; }
         public string Version => Assembly.GetEntryAssembly().GetName().Version.ToString();
 
@@ -73,21 +71,19 @@ namespace IW4MAdmin.Application
             PageList = new PageList();
             AdditionalEventParsers = new List<IEventParser>();
             AdditionalRConParsers = new List<IRConParser>();
-            OnServerEvent += OnGameEvent;
-            OnServerEvent += EventApi.OnGameEvent;
+            //OnServerEvent += OnGameEvent;
+            //OnServerEvent += EventApi.OnGameEvent;
             TokenAuthenticator = new TokenAuthentication();
             _metaService = new MetaService();
             _tokenSource = new CancellationTokenSource();
         }
 
-        private async void OnGameEvent(object sender, GameEventArgs args)
+        public async Task ExecuteEvent(GameEvent newEvent)
         {
 #if DEBUG == true
-            Logger.WriteDebug($"Entering event process for {args.Event.Id}");
+            Logger.WriteDebug($"Entering event process for {newEvent.Id}");
 #endif
 
-            var newEvent = args.Event;
-
             // the event has failed already
             if (newEvent.Failed)
             {
@@ -96,12 +92,11 @@ namespace IW4MAdmin.Application
 
             try
             {
-                await newEvent.Owner.EventProcessing.WaitAsync(CancellationToken);
                 await newEvent.Owner.ExecuteEvent(newEvent);
 
                 // save the event info to the database
                 var changeHistorySvc = new ChangeHistoryService();
-                await changeHistorySvc.Add(args.Event);
+                await changeHistorySvc.Add(newEvent);
 
 #if DEBUG
                 Logger.WriteDebug($"Processed event with id {newEvent.Id}");
@@ -145,22 +140,12 @@ namespace IW4MAdmin.Application
                 Logger.WriteDebug(ex.GetExceptionInfo());
             }
 
-            finally
-            {
-                if (newEvent.Owner.EventProcessing.CurrentCount == 0)
-                {
-                    newEvent.Owner.EventProcessing.Release(1);
-                }
-
-#if DEBUG == true
-                Logger.WriteDebug($"Exiting event process for {args.Event.Id}");
-#endif
-            }
-
         skip:
-
             // tell anyone waiting for the output that we're done
-            newEvent.OnProcessed.Set();
+            newEvent.Complete();
+#if DEBUG == true
+            Logger.WriteDebug($"Exiting event process for {newEvent.Id}");
+#endif
         }
 
         public IList<Server> GetServers()

Application/EventParsers/BaseEventParser.cs

@@ -256,6 +256,7 @@ namespace IW4MAdmin.Application.EventParsers
             // this is a custom event printed out by _customcallbacks.gsc (used for anticheat)
             if (eventType == "ScriptKill")
             {
+                
                 long originId = lineSplit[1].ConvertGuidToLong(1);
                 long targetId = lineSplit[2].ConvertGuidToLong(1);
 

Application/GameEventHandler.cs

@@ -1,6 +1,8 @@
-using SharedLibraryCore;
+using IW4MAdmin.Application.Misc;
+using SharedLibraryCore;
 using SharedLibraryCore.Events;
 using SharedLibraryCore.Interfaces;
+using System;
 using System.Linq;
 using System.Threading;
 
@@ -9,7 +11,11 @@ namespace IW4MAdmin.Application
     class GameEventHandler : IEventHandler
     {
         readonly ApplicationManager Manager;
-        private static GameEvent.EventType[] overrideEvents = new[]
+        private readonly EventProfiler _profiler;
+        private delegate void GameEventAddedEventHandler(object sender, GameEventArgs args);
+        private event GameEventAddedEventHandler GameEventAdded;
+
+        private static readonly GameEvent.EventType[] overrideEvents = new[]
         {
             GameEvent.EventType.Connect,
             GameEvent.EventType.Disconnect,
@@ -20,6 +26,17 @@ namespace IW4MAdmin.Application
         public GameEventHandler(IManager mgr)
         {
             Manager = (ApplicationManager)mgr;
+            _profiler = new EventProfiler(mgr.GetLogger(0));
+            GameEventAdded += GameEventHandler_GameEventAdded;
+        }
+
+        private async void GameEventHandler_GameEventAdded(object sender, GameEventArgs args)
+        {
+            var start = DateTime.Now;
+            await Manager.ExecuteEvent(args.Event);
+#if DEBUG
+            _profiler.Profile(start, DateTime.Now, args.Event);
+#endif
         }
 
         public void AddEvent(GameEvent gameEvent)
@@ -35,7 +52,7 @@ namespace IW4MAdmin.Application
 #if DEBUG
                 gameEvent.Owner.Logger.WriteDebug($"Adding event with id {gameEvent.Id}");
 #endif
-                Manager.OnServerEvent?.Invoke(gameEvent.Owner, new GameEventArgs(null, false, gameEvent));
+                GameEventAdded?.Invoke(this, new GameEventArgs(null, false, gameEvent));
             }
 #if DEBUG
             else

Application/IO/GameLogEventDetection.cs

@@ -76,7 +76,6 @@ namespace IW4MAdmin.Application.IO
 #if DEBUG
                     _server.Logger.WriteVerbose(gameEvent.Data);
 #endif
-
                     // we don't want to add the event if ignoreBots is on and the event comes from a bot
                     if (!_ignoreBots || (_ignoreBots && !((gameEvent.Origin?.IsBot ?? false) || (gameEvent.Target?.IsBot ?? false))))
                     {
@@ -103,11 +102,6 @@ namespace IW4MAdmin.Application.IO
                         }
 
                         _server.Manager.GetEventHandler().AddEvent(gameEvent);
-
-                        if (gameEvent.IsBlocking)
-                        {
-                            await gameEvent.WaitAsync(Utilities.DefaultCommandTimeout, _server.Manager.CancellationToken);
-                        }
                     }
                 }
 

Application/IW4MServer.cs

@@ -33,7 +33,7 @@ namespace IW4MAdmin
         {
         }
 
-        override public async Task OnClientConnected(EFClient clientFromLog)
+        override public async Task<EFClient> OnClientConnected(EFClient clientFromLog)
         {
             Logger.WriteDebug($"Client slot #{clientFromLog.ClientNumber} now reserved");
 
@@ -57,6 +57,7 @@ namespace IW4MAdmin
             Logger.WriteInfo($"Client {client} connected...");
 
             // Do the player specific stuff
+            client.ProcessingEvent = clientFromLog.ProcessingEvent;
             client.ClientNumber = clientFromLog.ClientNumber;
             client.Score = clientFromLog.Score;
             client.Ping = clientFromLog.Ping;
@@ -73,9 +74,8 @@ namespace IW4MAdmin
                 Type = GameEvent.EventType.Connect
             };
 
-            await client.OnJoin(client.IPAddress);
-            client.State = ClientState.Connected;
             Manager.GetEventHandler().AddEvent(e);
+            return client;
         }
 
         override public async Task OnClientDisconnected(EFClient client)
@@ -103,55 +103,85 @@ namespace IW4MAdmin
 
         public override async Task ExecuteEvent(GameEvent E)
         {
-            bool canExecuteCommand = true;
-
-            if (!await ProcessEvent(E))
+            if (E == null)
             {
+                Logger.WriteError("Received NULL event");
                 return;
             }
 
-            Command C = null;
-            if (E.Type == GameEvent.EventType.Command)
+            if (E.IsBlocking)
             {
-                try
+                await E.Origin?.Lock();
+            }
+
+            bool canExecuteCommand = true;
+            Exception lastException = null;
+
+            try
+            {
+                if (!await ProcessEvent(E))
                 {
-                    C = await SharedLibraryCore.Commands.CommandProcessing.ValidateCommand(E);
+                    return;
                 }
 
-                catch (CommandException e)
+                Command C = null;
+                if (E.Type == GameEvent.EventType.Command)
                 {
-                    Logger.WriteInfo(e.Message);
+                    try
+                    {
+                        C = await SharedLibraryCore.Commands.CommandProcessing.ValidateCommand(E);
+                    }
+
+                    catch (CommandException e)
+                    {
+                        Logger.WriteInfo(e.Message);
+                    }
+
+                    if (C != null)
+                    {
+                        E.Extra = C;
+                    }
                 }
 
-                if (C != null)
+                foreach (var plugin in SharedLibraryCore.Plugins.PluginImporter.ActivePlugins)
                 {
-                    E.Extra = C;
+                    try
+                    {
+                        await plugin.OnEventAsync(E, this);
+                    }
+                    catch (AuthorizationException e)
+                    {
+                        E.Origin.Tell($"{loc["COMMAND_NOTAUTHORIZED"]} - {e.Message}");
+                        canExecuteCommand = false;
+                    }
+                    catch (Exception Except)
+                    {
+                        Logger.WriteError($"{loc["SERVER_PLUGIN_ERROR"]} [{plugin.Name}]");
+                        Logger.WriteDebug(Except.GetExceptionInfo());
+                    }
+                }
+
+                // hack: this prevents commands from getting executing that 'shouldn't' be
+                if (E.Type == GameEvent.EventType.Command && E.Extra is Command command &&
+                    (canExecuteCommand || E.Origin?.Level == Permission.Console))
+                {
+                    await command.ExecuteAsync(E);
                 }
             }
 
-            foreach (var plugin in SharedLibraryCore.Plugins.PluginImporter.ActivePlugins)
+            catch (Exception e)
             {
-                try
-                {
-                    await plugin.OnEventAsync(E, this);
-                }
-                catch (AuthorizationException e)
-                {
-                    E.Origin.Tell($"{loc["COMMAND_NOTAUTHORIZED"]} - {e.Message}");
-                    canExecuteCommand = false;
-                }
-                catch (Exception Except)
-                {
-                    Logger.WriteError($"{loc["SERVER_PLUGIN_ERROR"]} [{plugin.Name}]");
-                    Logger.WriteDebug(Except.GetExceptionInfo());
-                }
+                lastException = e;
             }
 
-            // hack: this prevents commands from getting executing that 'shouldn't' be
-            if (E.Type == GameEvent.EventType.Command && E.Extra is Command command &&
-                (canExecuteCommand || E.Origin?.Level == Permission.Console))
+            finally
             {
-                await command.ExecuteAsync(E);
+                E.Origin?.Unlock();
+
+                if (lastException != null)
+                {
+                    throw lastException;
+                }
             }
         }
 
@@ -195,6 +225,25 @@ namespace IW4MAdmin
                 await Manager.GetClientService().UpdateLevel(newPermission, E.Target, E.Origin);
             }
 
+            else if (E.Type == GameEvent.EventType.Connect)
+            {
+                if (E.Origin.State != ClientState.Connected)
+                {
+                    E.Origin.State = ClientState.Connected;
+                    E.Origin.LastConnection = DateTime.UtcNow;
+                    E.Origin.Connections += 1;
+
+                    ChatHistory.Add(new ChatInfo()
+                    {
+                        Name = E.Origin.Name,
+                        Message = "CONNECTED",
+                        Time = DateTime.UtcNow
+                    });
+
+                    await E.Origin.OnJoin(E.Origin.IPAddress);
+                }
+            }
+
             else if (E.Type == GameEvent.EventType.PreConnect)
             {
                 // we don't want to track bots in the database at all if ignore bots is requested
@@ -230,7 +279,8 @@ namespace IW4MAdmin
                     Clients[E.Origin.ClientNumber] = E.Origin;
                     try
                     {
-                        await OnClientConnected(E.Origin);
+                        E.Origin = await OnClientConnected(E.Origin);
+                        E.Target = E.Origin;
                     }
 
                     catch (Exception ex)
@@ -242,13 +292,6 @@ namespace IW4MAdmin
                         return false;
                     }
 
-                    ChatHistory.Add(new ChatInfo()
-                    {
-                        Name = E.Origin.Name,
-                        Message = "CONNECTED",
-                        Time = DateTime.UtcNow
-                    });
-
                     if (E.Origin.Level > EFClient.Permission.Moderator)
                     {
                         E.Origin.Tell(string.Format(loc["SERVER_REPORT_COUNT"], E.Owner.Reports.Count));
@@ -624,7 +667,6 @@ namespace IW4MAdmin
 #endif
 
                     var polledClients = await PollPlayersAsync();
-                    var waiterList = new List<GameEvent>();
 
                     foreach (var disconnectingClient in polledClients[1])
                     {
@@ -641,18 +683,9 @@ namespace IW4MAdmin
                         };
 
                         Manager.GetEventHandler().AddEvent(e);
-                        // wait until the disconnect event is complete
-                        // because we don't want to try to fill up a slot that's not empty yet
-                        waiterList.Add(e);
+                        await e.WaitAsync(Utilities.DefaultCommandTimeout, Manager.CancellationToken);
                     }
 
-                    // wait for all the disconnect tasks to finish
-                    foreach (var waiter in waiterList)
-                    {
-                        waiter.Wait();
-                    }
-
-                    waiterList.Clear();
                     // this are our new connecting clients
                     foreach (var client in polledClients[0])
                     {
@@ -671,16 +704,9 @@ namespace IW4MAdmin
                         };
 
                         Manager.GetEventHandler().AddEvent(e);
-                        waiterList.Add(e);
+                        await e.WaitAsync(Utilities.DefaultCommandTimeout, Manager.CancellationToken);
                     }
 
-                    // wait for all the connect tasks to finish
-                    foreach (var waiter in waiterList)
-                    {
-                        waiter.Wait();
-                    }
-
-                    waiterList.Clear();
                     // these are the clients that have updated
                     foreach (var client in polledClients[2])
                     {
@@ -692,12 +718,6 @@ namespace IW4MAdmin
                         };
 
                         Manager.GetEventHandler().AddEvent(e);
-                        waiterList.Add(e);
-                    }
-
-                    foreach (var waiter in waiterList)
-                    {
-                        waiter.Wait();
                     }
 
                     if (ConnectionErrors > 0)

Application/Misc/EventProfiler.cs

@@ -0,0 +1,63 @@
+using SharedLibraryCore;
+using SharedLibraryCore.Interfaces;
+using System;
+using System.Collections.Generic;
+using System.Linq;
+
+namespace IW4MAdmin.Application.Misc
+{
+    internal class EventPerformance
+    {
+        public long ExecutionTime { get; set; }
+        public GameEvent Event { get; set; }
+        public string EventInfo => $"{Event.Type}, {Event.FailReason}, {Event.IsBlocking}, {Event.Data}, {Event.Message}, {Event.Extra}";
+    }
+
+    public class DuplicateKeyComparer<TKey> : IComparer<TKey> where TKey : IComparable
+    {
+        public int Compare(TKey x, TKey y)
+        {
+            int result = x.CompareTo(y);
+
+            if (result == 0)
+                return 1;
+            else
+                return result;
+        }
+    }
+
+    internal class EventProfiler
+    {
+        public double AverageEventTime { get; private set; }
+        public double MaxEventTime => Events.Values.Last().ExecutionTime;
+        public double MinEventTime => Events.Values[0].ExecutionTime;
+        public int TotalEventCount => Events.Count;
+        public SortedList<long, EventPerformance> Events { get; private set; } = new SortedList<long, EventPerformance>(new DuplicateKeyComparer<long>());
+        private readonly ILogger _logger;
+
+        public EventProfiler(ILogger logger)
+        {
+            _logger = logger;
+        }
+
+        public void Profile(DateTime start, DateTime end, GameEvent gameEvent)
+        {
+            _logger.WriteDebug($"Starting profile of event {gameEvent.Id}");
+            long executionTime = (long)Math.Round((end - start).TotalMilliseconds);
+
+            var perf = new EventPerformance()
+            {
+                Event = gameEvent,
+                ExecutionTime = executionTime
+            };
+
+            lock (Events)
+            {
+                Events.Add(executionTime, perf);
+            }
+
+            AverageEventTime = (AverageEventTime * (TotalEventCount - 1) + executionTime) / TotalEventCount;
+            _logger.WriteDebug($"Finished profile of event {gameEvent.Id}");
+        }
+    }
+}

Application/Misc/Logger.cs

@@ -3,7 +3,6 @@ using SharedLibraryCore.Interfaces;
 using System;
 using System.IO;
 using System.Threading;
-using System.Threading.Tasks;
 
 namespace IW4MAdmin.Application
 {
@@ -20,16 +19,21 @@ namespace IW4MAdmin.Application
         }
 
         readonly string FileName;
-        readonly SemaphoreSlim OnLogWriting;
+        readonly ReaderWriterLockSlim WritingLock;
         static readonly short MAX_LOG_FILES = 10;
 
         public Logger(string fn)
         {
             FileName = Path.Join(Utilities.OperatingDirectory, "Log", $"{fn}.log");
-            OnLogWriting = new SemaphoreSlim(1, 1);
+            WritingLock = new ReaderWriterLockSlim();
             RotateLogs();
         }
 
+        ~Logger()
+        {
+            WritingLock.Dispose();
+        }
+
         /// <summary>
         /// rotates logs when log is initialized
         /// </summary>
@@ -56,7 +60,7 @@ namespace IW4MAdmin.Application
 
         void Write(string msg, LogType type)
         {
-            OnLogWriting.Wait();
+            WritingLock.EnterWriteLock();
 
             string stringType = type.ToString();
             msg = msg.StripColors();
@@ -74,7 +78,7 @@ namespace IW4MAdmin.Application
 #if DEBUG
                 // lets keep it simple and dispose of everything quickly as logging wont be that much (relatively)
                 Console.WriteLine(LogLine);
-                File.AppendAllText(FileName, $"{LogLine}{Environment.NewLine}");
+                //File.AppendAllText(FileName, $"{LogLine}{Environment.NewLine}");
                 //Debug.WriteLine(msg);
 #else
                 if (type == LogType.Error || type == LogType.Verbose)
@@ -91,7 +95,7 @@ namespace IW4MAdmin.Application
                 Console.WriteLine(ex.GetExceptionInfo());
             }
 
-            OnLogWriting.Release(1);
+            WritingLock.ExitWriteLock();
         }
 
         public void WriteVerbose(string msg)

Application/RconParsers/BaseRConParser.cs

@@ -38,7 +38,7 @@ namespace IW4MAdmin.Application.RconParsers
                 },
             };
 
-            Configuration.Status.Pattern = @"^ *([0-9]+) +-?([0-9]+) +((?:[A-Z]+|[0-9]+)) +((?:[a-z]|[0-9]){8,32}|(?:[a-z]|[0-9]){8,32}|bot[0-9]+|(?:[0-9]+)) *(.{0,32}) +([0-9]+) +(\d+\.\d+\.\d+.\d+\:-*\d{1,5}|0+.0+:-*\d{1,5}|loopback) +(-*[0-9]+) +([0-9]+) *$";
+            Configuration.Status.Pattern = @"^ *([0-9]+) +-?([0-9]+) +((?:[A-Z]+|[0-9]+)) +((?:[a-z]|[0-9]){8,32}|(?:[a-z]|[0-9]){8,32}|bot[0-9]+|(?:[0-9]+)) *(.{0,32}) +([0-9]+) +(\d+\.\d+\.\d+.\d+\:-*\d{1,5}|0+.0+:-*\d{1,5}|loopback|unknown) +(-*[0-9]+) +([0-9]+) *$";
             Configuration.Status.AddMapping(ParserRegex.GroupType.RConClientNumber, 1);
             Configuration.Status.AddMapping(ParserRegex.GroupType.RConScore, 2);
             Configuration.Status.AddMapping(ParserRegex.GroupType.RConPing, 3);