From 16d7ccd590e2738879b4dac30d237f129981ada3 Mon Sep 17 00:00:00 2001 From: RaidMax Date: Wed, 4 Jul 2018 21:09:42 -0500 Subject: [PATCH] fix parsing of certain chat messages print out the correct exception message when a server is not responding. prevent log reader from reading before the servers have initialized --- Application/EventParsers/IW4EventParser.cs | 33 +++--- Application/GameEventHandler.cs | 27 +---- Application/IO/GameLogEvent.cs | 13 ++- Application/Manager.cs | 64 ++++++------ Application/Server.cs | 111 +++++++++++++-------- SharedLibraryCore/Event.cs | 32 +++++- SharedLibraryCore/Objects/Player.cs | 3 + SharedLibraryCore/Utilities.cs | 1 + 8 files changed, 173 insertions(+), 111 deletions(-) diff --git a/Application/EventParsers/IW4EventParser.cs b/Application/EventParsers/IW4EventParser.cs index 39cc81f33..bf5f701f0 100644 --- a/Application/EventParsers/IW4EventParser.cs +++ b/Application/EventParsers/IW4EventParser.cs @@ -10,6 +10,8 @@ namespace IW4MAdmin.Application.EventParsers { class IW4EventParser : IEventParser { + private const string SayRegex = @"(say|sayteam);(.{16,32});([0-9]+)(.*);(.*)"; + public virtual GameEvent GetEvent(Server server, string logLine) { logLine = Regex.Replace(logLine, @"([0-9]+:[0-9]+ |^[0-9]+ )", "").Trim(); @@ -45,28 +47,35 @@ namespace IW4MAdmin.Application.EventParsers if (eventType == "say" || eventType == "sayteam") { - string message = lineSplit[4].Replace("\x15", ""); + var matchResult = Regex.Match(logLine, SayRegex); - if (message[0] == '!' || message[0] == '@') + if (matchResult.Success) { + string message = matchResult.Groups[5].ToString() + .Replace("\x15", "") + .Trim(); + + if (message[0] == '!' || message[0] == '@') + { + return new GameEvent() + { + Type = GameEvent.EventType.Command, + Data = message, + Origin = server.GetPlayersAsList().First(c => c.ClientNumber == Utilities.ClientIdFromString(lineSplit, 2)), + Owner = server, + Message = message + }; + } + return new GameEvent() { - Type = GameEvent.EventType.Command, + Type = GameEvent.EventType.Say, Data = message, Origin = server.GetPlayersAsList().First(c => c.ClientNumber == Utilities.ClientIdFromString(lineSplit, 2)), Owner = server, Message = message }; } - - return new GameEvent() - { - Type = GameEvent.EventType.Say, - Data = message, - Origin = server.GetPlayersAsList().First(c => c.ClientNumber == Utilities.ClientIdFromString(lineSplit, 2)), - Owner = server, - Message = message - }; } if (eventType == "ScriptKill") diff --git a/Application/GameEventHandler.cs b/Application/GameEventHandler.cs index 7c9483820..360204527 100644 --- a/Application/GameEventHandler.cs +++ b/Application/GameEventHandler.cs @@ -3,9 +3,6 @@ using SharedLibraryCore.Interfaces; using System; using System.Collections.Concurrent; using System.Collections.Generic; -using System.Linq; -using System.Text; -using System.Threading; namespace IW4MAdmin.Application { @@ -14,8 +11,6 @@ namespace IW4MAdmin.Application private ConcurrentQueue EventQueue; private Queue DelayedEventQueue; private IManager Manager; - private const int DelayAmount = 5000; - private DateTime LastDelayedEvent; public GameEventHandler(IManager mgr) { @@ -50,25 +45,7 @@ namespace IW4MAdmin.Application } public GameEvent GetNextEvent() - { - if (DelayedEventQueue.Count > 0 && - (DateTime.Now - LastDelayedEvent).TotalMilliseconds > DelayAmount) - { - LastDelayedEvent = DateTime.Now; -#if DEBUG - Manager.GetLogger().WriteDebug("Getting next delayed event to be processed"); -#endif - if (!DelayedEventQueue.TryDequeue(out GameEvent newEvent)) - { - Manager.GetLogger().WriteWarning("Could not dequeue delayed event for processing"); - } - - else - { - return newEvent; - } - } - + { if (EventQueue.Count > 0) { #if DEBUG @@ -76,7 +53,7 @@ namespace IW4MAdmin.Application #endif if (!EventQueue.TryDequeue(out GameEvent newEvent)) { - Manager.GetLogger().WriteWarning("Could not dequeue event for processing"); + Manager.GetLogger().WriteError("Could not dequeue event for processing"); } else diff --git a/Application/IO/GameLogEvent.cs b/Application/IO/GameLogEvent.cs index ddad05904..2bc18387f 100644 --- a/Application/IO/GameLogEvent.cs +++ b/Application/IO/GameLogEvent.cs @@ -29,11 +29,14 @@ namespace IW4MAdmin.Application.IO { while (!server.Manager.ShutdownRequested()) { - OnEvent(new EventState() + if ((server.Manager as ApplicationManager).IsInitialized) { - Log = server.Manager.GetLogger(), - ServerId = server.ToString() - }); + OnEvent(new EventState() + { + Log = server.Manager.GetLogger(), + ServerId = server.ToString() + }); + } await Task.Delay(100); } }); @@ -42,7 +45,7 @@ namespace IW4MAdmin.Application.IO private void OnEvent(object state) { long newLength = new FileInfo(GameLogFile).Length; - + try { UpdateLogEvents(newLength); diff --git a/Application/Manager.cs b/Application/Manager.cs index 0dd930dae..938156dab 100644 --- a/Application/Manager.cs +++ b/Application/Manager.cs @@ -31,6 +31,7 @@ namespace IW4MAdmin.Application public Dictionary PrivilegedClients { get; set; } public ILogger Logger { get; private set; } public bool Running { get; private set; } + public bool IsInitialized { get; private set; } public EventHandler ServerEventOccurred { get; private set; } public DateTime StartTime { get; private set; } @@ -92,6 +93,13 @@ namespace IW4MAdmin.Application .Select(ut => ut.Key) .ToList(); + // this is to prevent the log reader from starting before the initial + // query of players on the server + if (serverTasksToRemove.Count > 0) + { + IsInitialized = true; + } + // remove the update tasks as they have completd foreach (int serverId in serverTasksToRemove) { @@ -122,7 +130,11 @@ namespace IW4MAdmin.Application ThreadPool.GetAvailableThreads(out int availableThreads, out int m); Logger.WriteDebug($"There are {workerThreads - availableThreads} active threading tasks"); #endif +#if DEBUG + await Task.Delay(30000); +#else await Task.Delay(ConfigHandler.Configuration().RConPollRate); +#endif } } @@ -130,7 +142,7 @@ namespace IW4MAdmin.Application { Running = true; - #region DATABASE +#region DATABASE var ipList = (await ClientSvc.Find(c => c.Level > Player.Permission.Trusted)) .Select(c => new { @@ -160,9 +172,9 @@ namespace IW4MAdmin.Application continue; } } - #endregion +#endregion - #region CONFIG +#region CONFIG var config = ConfigHandler.Configuration(); // copy over default config if it doesn't exist @@ -213,8 +225,8 @@ namespace IW4MAdmin.Application Encoding.RegisterProvider(CodePagesEncodingProvider.Instance); Utilities.EncodingType = Encoding.GetEncoding(!string.IsNullOrEmpty(config.CustomParserEncoding) ? config.CustomParserEncoding : "windows-1252"); - #endregion - #region PLUGINS +#endregion +#region PLUGINS SharedLibraryCore.Plugins.PluginImporter.Load(this); foreach (var Plugin in SharedLibraryCore.Plugins.PluginImporter.ActivePlugins) @@ -231,9 +243,9 @@ namespace IW4MAdmin.Application Logger.WriteDebug($"Stack Trace: {e.StackTrace}"); } } - #endregion +#endregion - #region COMMANDS +#region COMMANDS if (ClientSvc.GetOwners().Result.Count == 0) Commands.Add(new COwner()); @@ -277,9 +289,9 @@ namespace IW4MAdmin.Application foreach (Command C in SharedLibraryCore.Plugins.PluginImporter.ActiveCommands) Commands.Add(C); - #endregion +#endregion - #region INIT +#region INIT async Task Init(ServerConfiguration Conf) { // setup the event handler after the class is initialized @@ -315,7 +327,7 @@ namespace IW4MAdmin.Application } await Task.WhenAll(config.Servers.Select(c => Init(c)).ToArray()); - #endregion +#endregion } private async Task SendHeartbeat(object state) @@ -414,8 +426,7 @@ namespace IW4MAdmin.Application catch (NetworkException e) { - Logger.WriteError(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_COMMUNICATION"]); - Logger.WriteDebug(e.Message); + Logger.WriteError(e.Message); } catch (Exception E) @@ -434,24 +445,21 @@ namespace IW4MAdmin.Application { // wait for new event to be added OnEvent.Wait(); - var taskList = new List(); - // todo: sequencially or parallelize? - while ((queuedEvent = Handler.GetNextEvent()) != null) + while((queuedEvent = Handler.GetNextEvent()) != null) { - if (queuedEvent.Origin != null && - !queuedEvent.Origin.IsAuthenticated && - // we want to allow join events - queuedEvent.Type != GameEvent.EventType.Join && - queuedEvent.Type != GameEvent.EventType.Quit && - // we don't care about unknown events - queuedEvent.Origin.NetworkId != 0) + if (GameEvent.ShouldOriginEventBeDelayed(queuedEvent)) { - Logger.WriteDebug($"Delaying execution of event type {queuedEvent.Type} for {queuedEvent.Origin} because they are not authed"); - // update the event origin for possible authed client - queuedEvent.Origin = queuedEvent.Owner.Players.FirstOrDefault(p => p != null && p.NetworkId == queuedEvent.Origin.NetworkId); - queuedEvent.Target = queuedEvent.Target == null ? null : queuedEvent.Owner.Players.FirstOrDefault(p => p != null && p.NetworkId == queuedEvent.Target.NetworkId); - // add it back to the queue for reprocessing - Handler.AddEvent(queuedEvent, true); + Logger.WriteDebug($"Delaying origin execution of event type {queuedEvent.Type} for {queuedEvent.Origin} because they are not authed"); + // offload it to the player to keep + queuedEvent.Origin.DelayedEvents.Enqueue(queuedEvent); + continue; + } + + if (GameEvent.ShouldTargetEventBeDelayed(queuedEvent)) + { + Logger.WriteDebug($"Delaying target execution of event type {queuedEvent.Type} for {queuedEvent.Target} because they are not authed"); + // offload it to the player to keep + queuedEvent.Target.DelayedEvents.Enqueue(queuedEvent); continue; } await processEvent(queuedEvent); diff --git a/Application/Server.cs b/Application/Server.cs index 6e2aabf5e..486826341 100644 --- a/Application/Server.cs +++ b/Application/Server.cs @@ -79,9 +79,7 @@ namespace IW4MAdmin if (Players[polledPlayer.ClientNumber] != null && Players[polledPlayer.ClientNumber].NetworkId == polledPlayer.NetworkId && - // only update if they're unauthenticated - Players[polledPlayer.ClientNumber].IsAuthenticated && - Players[polledPlayer.ClientNumber].State == Player.ClientState.Connected) + Players[polledPlayer.ClientNumber].State == Player.ClientState.Connected) { // update their ping & score Players[polledPlayer.ClientNumber].Ping = polledPlayer.Ping; @@ -89,18 +87,19 @@ namespace IW4MAdmin return true; } - if (Players[polledPlayer.ClientNumber] != null && - Players[polledPlayer.ClientNumber].State == Player.ClientState.Connected) + if (Players[polledPlayer.ClientNumber] == null) + { + Players[polledPlayer.ClientNumber] = polledPlayer; + } + + if (!polledPlayer.IsAuthenticated) { return true; } + // if they're authenticated but haven't been added yet + // we want to set their delayed events + var delayedEventQueue = Players[polledPlayer.ClientNumber].DelayedEvents; - if (Players[polledPlayer.ClientNumber] == null) - { - //prevent duplicates from being added - polledPlayer.State = Player.ClientState.Connecting; - Players[polledPlayer.ClientNumber] = polledPlayer; - } #if !DEBUG if (polledPlayer.Name.Length < 3) { @@ -175,15 +174,20 @@ namespace IW4MAdmin await Manager.GetClientService().Update(client); } - else if (existingAlias.Name == polledPlayer.Name) + else if (existingAlias.Name == polledPlayer.Name || + // fixme: why would this be null? + client.CurrentAlias == null) { client.CurrentAlias = existingAlias; client.CurrentAliasId = existingAlias.AliasId; client = await Manager.GetClientService().Update(client); } + player = client.AsPlayer(); } + Logger.WriteInfo($"Client {player} connected..."); + // Do the player specific stuff player.ClientNumber = polledPlayer.ClientNumber; player.IsBot = polledPlayer.IsBot; @@ -230,8 +234,6 @@ namespace IW4MAdmin return true; } - Logger.WriteInfo($"Client {player} connecting..."); - if (!Manager.GetApplicationSettings().Configuration().EnableClientVPNs && await VPNCheck.UsingVPN(player.IPAddressString, Manager.GetApplicationSettings().Configuration().IPHubAPIKey)) { @@ -247,12 +249,33 @@ namespace IW4MAdmin }; Manager.GetEventHandler().AddEvent(e); + // add the delayed event to the queue + while (delayedEventQueue?.Count > 0) + { + e = delayedEventQueue.Dequeue(); + e.Origin = player; + // check if the target was assigned + if (e.Target != null) + { + // update the target incase they left or have newer info + e.Target = GetPlayersAsList().FirstOrDefault(p => p.NetworkId == e.Target.NetworkId); + // we have to throw out the event because they left + if (e.Target == null) + { + Logger.WriteWarning($"Delayed event for {e.Origin} was removed because the target has left"); + continue; + } + } + Manager.GetEventHandler().AddEvent(e); + } + return true; } catch (Exception E) { Manager.GetLogger().WriteError($"{loc["SERVER_ERROR_ADDPLAYER"]} {polledPlayer.Name}::{polledPlayer.NetworkId}"); + Manager.GetLogger().WriteDebug(E.Message); Manager.GetLogger().WriteDebug(E.StackTrace); return false; } @@ -381,33 +404,42 @@ namespace IW4MAdmin else if (E.Type == GameEvent.EventType.Quit) { - var e = new GameEvent() - { - Type = GameEvent.EventType.Disconnect, - Origin = Players.FirstOrDefault(p => p != null && p.NetworkId == E.Origin.NetworkId), - Owner = this - }; + var origin = Players.FirstOrDefault(p => p != null && p.NetworkId == E.Origin.NetworkId); - if (e.Origin != null) + if (origin != null && + // we only want to forward the event if they are connected. + origin.State == Player.ClientState.Connected) { - e.Origin.State = Player.ClientState.Disconnecting; + var e = new GameEvent() + { + Type = GameEvent.EventType.Disconnect, + Origin = origin, + Owner = this + }; + + if (e.Origin != null) + { + e.Origin.State = Player.ClientState.Disconnecting; + } + + Manager.GetEventHandler().AddEvent(e); } - Manager.GetEventHandler().AddEvent(e); + else if (origin != null && + origin.State == Player.ClientState.Connecting) + { + await RemovePlayer(origin.ClientNumber); + } } else if (E.Type == GameEvent.EventType.Disconnect) { - // this may be a fix for a hard to reproduce null exception error - lock (ChatHistory) + ChatHistory.Add(new ChatInfo() { - ChatHistory.Add(new ChatInfo() - { - Name = E.Origin.Name, - Message = "DISCONNECTED", - Time = DateTime.UtcNow - }); - } + Name = E.Origin.Name, + Message = "DISCONNECTED", + Time = DateTime.UtcNow + }); await RemovePlayer(E.Origin.ClientNumber); } @@ -498,7 +530,6 @@ namespace IW4MAdmin ChatHistory.Clear(); } - async Task PollPlayersAsync() { var now = DateTime.Now; @@ -546,14 +577,14 @@ namespace IW4MAdmin AuthQueue.AuthenticateClients(CurrentPlayers); + // all polled players should be authenticated - foreach (var client in AuthQueue.GetAuthenticatedClients()) - { - if (Players[client.ClientNumber] == null || Players[client.ClientNumber].State == Player.ClientState.Connecting) - { - await AddPlayer(client); - } - } + var addPlayerTasks = AuthQueue.GetAuthenticatedClients() + .Where(client => Players[client.ClientNumber] == null || + Players[client.ClientNumber].State == Player.ClientState.Connecting) + .Select(client => AddPlayer(client)); + + await Task.WhenAll(addPlayerTasks); return CurrentPlayers.Count; } diff --git a/SharedLibraryCore/Event.cs b/SharedLibraryCore/Event.cs index a8dae929e..e577ef379 100644 --- a/SharedLibraryCore/Event.cs +++ b/SharedLibraryCore/Event.cs @@ -9,7 +9,7 @@ namespace SharedLibraryCore public enum EventType { Unknown, - + // events "generated" by the server Start, Stop, @@ -76,5 +76,35 @@ namespace SharedLibraryCore public ManualResetEventSlim OnProcessed { get; set; } public DateTime Time { get; private set; } public long Id { get; private set; } + + /// + /// determine whether an event should be delayed or not + /// applies only to the origin entity + /// + /// event to determine status for + /// true if event should be delayed, false otherwise + public static bool ShouldOriginEventBeDelayed(GameEvent queuedEvent) + { + return queuedEvent.Origin != null && + !queuedEvent.Origin.IsAuthenticated && + // we want to allow join and quit events + queuedEvent.Type != EventType.Join && + queuedEvent.Type != EventType.Quit && + // we don't care about unknown events + queuedEvent.Origin.NetworkId != 0; + } + + /// + /// determine whether an event should be delayed or not + /// applies only to the target entity + /// + /// event to determine status for + /// true if event should be delayed, false otherwise + public static bool ShouldTargetEventBeDelayed(GameEvent queuedEvent) + { + return queuedEvent.Target != null && + !queuedEvent.Target.IsAuthenticated && + queuedEvent.Target.NetworkId != 0; + } } } diff --git a/SharedLibraryCore/Objects/Player.cs b/SharedLibraryCore/Objects/Player.cs index 9261e6e45..8a6b31ded 100644 --- a/SharedLibraryCore/Objects/Player.cs +++ b/SharedLibraryCore/Objects/Player.cs @@ -33,6 +33,7 @@ namespace SharedLibraryCore.Objects { ConnectionTime = DateTime.UtcNow; ClientNumber = -1; + DelayedEvents = new Queue(); } public override string ToString() @@ -120,6 +121,8 @@ namespace SharedLibraryCore.Objects public bool IsAuthenticated { get; set; } [NotMapped] public ClientState State { get; set; } + [NotMapped] + public Queue DelayedEvents { get; set; } public override bool Equals(object obj) { diff --git a/SharedLibraryCore/Utilities.cs b/SharedLibraryCore/Utilities.cs index ef5d8ca2d..d44b226e5 100644 --- a/SharedLibraryCore/Utilities.cs +++ b/SharedLibraryCore/Utilities.cs @@ -327,6 +327,7 @@ namespace SharedLibraryCore LastConnection = client.LastConnection == DateTime.MinValue ? DateTime.UtcNow : client.LastConnection, CurrentAlias = client.CurrentAlias, CurrentAliasId = client.CurrentAlias.AliasId, + // todo: make sure this is up to date IsBot = client.NetworkId == -1, Password = client.Password, PasswordSalt = client.PasswordSalt