From 570a228c9255f2717b1e9a14e5d08cc2bbd288fd Mon Sep 17 00:00:00 2001 From: RaidMax Date: Wed, 11 Nov 2020 17:31:26 -0600 Subject: [PATCH] refactor logging in pretty big overhaul --- .gitignore | 1 + Application/API/Master/IMasterApi.cs | 2 +- Application/Application.csproj | 5 + Application/ApplicationManager.cs | 181 ++- Application/BuildScripts/PostBuild.bat | 15 +- .../Configuration/LoggingConfiguration.json | 43 + Application/EventParsers/BaseEventParser.cs | 4 +- .../EventParsers/DynamicEventParser.cs | 1 + Application/Extensions/StartupExtensions.cs | 41 + Application/Factories/GameLogReaderFactory.cs | 5 +- .../Factories/GameServerInstanceFactory.cs | 16 +- .../Factories/RConConnectionFactory.cs | 5 +- Application/Factories/ScriptCommandFactory.cs | 14 +- Application/GameEventHandler.cs | 24 +- Application/IO/GameLogEventDetection.cs | 28 +- Application/IO/GameLogReader.cs | 8 +- Application/IO/GameLogReaderHttp.cs | 10 +- Application/IW4MServer.cs | 1035 +++++++++-------- Application/Localization/Configure.cs | 22 +- Application/Main.cs | 192 +-- .../AdministeredPenaltyResourceQueryHelper.cs | 4 +- Application/Meta/MetaRegistration.cs | 6 +- .../ReceivedPenaltyResourceQueryHelper.cs | 4 +- .../Meta/UpdatedAliasResourceQueryHelper.cs | 4 +- .../Migration/ConfigurationMigration.cs | 8 +- Application/Misc/EventProfiler.cs | 63 - Application/Misc/Logger.cs | 113 +- Application/Misc/MasterCommunication.cs | 23 +- Application/Misc/MetaService.cs | 4 +- Application/Misc/MiddlewareActionHandler.cs | 10 +- Application/Misc/PluginImporter.cs | 25 +- Application/Misc/RemoteAssemblyHandler.cs | 12 +- Application/Misc/ScriptCommand.cs | 17 +- Application/Misc/ScriptPlugin.cs | 57 +- Application/RCon/RConConnection.cs | 101 +- Application/RconParsers/BaseRConParser.cs | 14 +- Application/RconParsers/DynamicRConParser.cs | 5 +- .../AutomessageFeed/AutomessageFeed.csproj | 2 +- .../IW4ScriptCommands.csproj | 2 +- Plugins/LiveRadar/LiveRadar.csproj | 2 +- Plugins/LiveRadar/Plugin.cs | 12 +- Plugins/Login/Login.csproj | 2 +- .../ProfanityDeterment.csproj | 2 +- Plugins/ScriptPlugins/ParserIW6x.js | 2 +- .../SampleScriptPluginCommand.js | 1 + Plugins/Stats/Cheat/Detection.cs | 19 +- Plugins/Stats/Cheat/Strain.cs | 6 - Plugins/Stats/Helpers/MigrationHelper.cs | 7 + Plugins/Stats/Helpers/StatManager.cs | 56 +- Plugins/Stats/Plugin.cs | 39 +- Plugins/Stats/Stats.csproj | 4 +- Plugins/Web/StatsWeb/API/StatsController.cs | 8 +- .../Web/StatsWeb/ChatResourceQueryHelper.cs | 4 +- .../StatsWeb/Controllers/StatsController.cs | 16 +- Plugins/Web/StatsWeb/StatsWeb.csproj | 4 +- Plugins/Welcome/Welcome.csproj | 2 +- SharedLibraryCore/Command.cs | 1 + SharedLibraryCore/Commands/NativeCommands.cs | 11 +- SharedLibraryCore/Events/GameEvent.cs | 21 +- SharedLibraryCore/Exceptions/RConException.cs | 11 + SharedLibraryCore/Interfaces/ILogger.cs | 5 +- SharedLibraryCore/Interfaces/IManager.cs | 2 + SharedLibraryCore/PartialEntities/EFClient.cs | 261 +++-- SharedLibraryCore/RCon/StaticHelpers.cs | 5 +- SharedLibraryCore/Server.cs | 45 +- .../Services/ChangeHistoryService.cs | 12 +- SharedLibraryCore/Services/ClientService.cs | 272 +++-- SharedLibraryCore/SharedLibraryCore.csproj | 8 +- SharedLibraryCore/Utilities.cs | 7 +- .../ApplicationTests/BaseEventParserTests.cs | 17 +- Tests/ApplicationTests/BaseRConParserTests.cs | 9 +- Tests/ApplicationTests/CommandTests.cs | 3 - .../DependencyInjectionExtensions.cs | 20 +- Tests/ApplicationTests/IW4MServerTests.cs | 7 +- Tests/ApplicationTests/PluginTests.cs | 6 +- Tests/ApplicationTests/ServerTests.cs | 18 +- Tests/ApplicationTests/StatsTests.cs | 17 +- .../Controllers/API/ClientController.cs | 8 +- WebfrontCore/Controllers/ClientController.cs | 2 +- WebfrontCore/Controllers/HomeController.cs | 12 +- WebfrontCore/Middleware/IPWhitelist.cs | 15 +- WebfrontCore/Startup.cs | 14 +- WebfrontCore/Views/Client/Find/Index.cshtml | 2 +- .../Components/PenaltyList/_List.cshtml | 2 +- .../Views/Shared/ResponseStatusCode.cshtml | 4 +- WebfrontCore/WebfrontCore.csproj | 8 +- 86 files changed, 1603 insertions(+), 1534 deletions(-) create mode 100644 Application/Configuration/LoggingConfiguration.json create mode 100644 Application/Extensions/StartupExtensions.cs delete mode 100644 Application/Misc/EventProfiler.cs create mode 100644 Plugins/Stats/Helpers/MigrationHelper.cs create mode 100644 SharedLibraryCore/Exceptions/RConException.cs diff --git a/.gitignore b/.gitignore index f5c4f09f1..f77430567 100644 --- a/.gitignore +++ b/.gitignore @@ -244,3 +244,4 @@ launchSettings.json /Tests/ApplicationTests/Files/GameEvents.json /Tests/ApplicationTests/Files/replay.json /GameLogServer/game_log_server_env +.idea/* \ No newline at end of file diff --git a/Application/API/Master/IMasterApi.cs b/Application/API/Master/IMasterApi.cs index f6a46bf21..2b99422af 100644 --- a/Application/API/Master/IMasterApi.cs +++ b/Application/API/Master/IMasterApi.cs @@ -1,7 +1,7 @@ using System; using System.Collections.Generic; using System.Threading.Tasks; -using IW4MAdmin.Application.Helpers; +using IW4MAdmin.Application.Misc; using Newtonsoft.Json; using RestEase; using SharedLibraryCore.Helpers; diff --git a/Application/Application.csproj b/Application/Application.csproj index b0ef4959c..8665b7505 100644 --- a/Application/Application.csproj +++ b/Application/Application.csproj @@ -21,6 +21,8 @@ IW4MAdmin.Application false + 2020.0.0.0 + 2020.0.0.0 @@ -59,6 +61,9 @@ Always + + PreserveNewest + diff --git a/Application/ApplicationManager.cs b/Application/ApplicationManager.cs index 135e02562..5324bc051 100644 --- a/Application/ApplicationManager.cs +++ b/Application/ApplicationManager.cs @@ -1,5 +1,4 @@ -using IW4MAdmin.Application.API.Master; -using IW4MAdmin.Application.EventParsers; +using IW4MAdmin.Application.EventParsers; using IW4MAdmin.Application.Extensions; using IW4MAdmin.Application.Misc; using IW4MAdmin.Application.RconParsers; @@ -9,11 +8,9 @@ using SharedLibraryCore.Configuration; using SharedLibraryCore.Configuration.Validation; using SharedLibraryCore.Database; using SharedLibraryCore.Database.Models; -using SharedLibraryCore.Dtos; using SharedLibraryCore.Exceptions; using SharedLibraryCore.Helpers; using SharedLibraryCore.Interfaces; -using SharedLibraryCore.QueryHelper; using SharedLibraryCore.Services; using System; using System.Collections; @@ -24,7 +21,12 @@ using System.Reflection; using System.Text; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Serilog.Context; using static SharedLibraryCore.GameEvent; +using ILogger = Microsoft.Extensions.Logging.ILogger; +using ObsoleteLogger = SharedLibraryCore.Interfaces.ILogger; namespace IW4MAdmin.Application { @@ -32,7 +34,7 @@ namespace IW4MAdmin.Application { private readonly ConcurrentBag _servers; public List Servers => _servers.OrderByDescending(s => s.ClientNum).ToList(); - public ILogger Logger => GetLogger(0); + [Obsolete] public ObsoleteLogger Logger => _serviceProvider.GetRequiredService(); public bool IsRunning { get; private set; } public bool IsInitialized { get; private set; } public DateTime StartTime { get; private set; } @@ -54,7 +56,6 @@ namespace IW4MAdmin.Application readonly PenaltyService PenaltySvc; public IConfigurationHandler ConfigHandler; readonly IPageList PageList; - private readonly Dictionary _loggers = new Dictionary(); private readonly IMetaService _metaService; private readonly TimeSpan _throttleTimeout = new TimeSpan(0, 1, 0); private readonly CancellationTokenSource _tokenSource; @@ -68,30 +69,33 @@ namespace IW4MAdmin.Application private readonly IScriptCommandFactory _scriptCommandFactory; private readonly IMetaRegistration _metaRegistration; private readonly IScriptPluginServiceResolver _scriptPluginServiceResolver; + private readonly IServiceProvider _serviceProvider; + private readonly ChangeHistoryService _changeHistoryService; + private readonly ApplicationConfiguration _appConfig; - public ApplicationManager(ILogger logger, IMiddlewareActionHandler actionHandler, IEnumerable commands, + public ApplicationManager(ILogger logger, IMiddlewareActionHandler actionHandler, IEnumerable commands, ITranslationLookup translationLookup, IConfigurationHandler commandConfiguration, IConfigurationHandler appConfigHandler, IGameServerInstanceFactory serverInstanceFactory, IEnumerable plugins, IParserRegexFactory parserRegexFactory, IEnumerable customParserEvents, IEventHandler eventHandler, IScriptCommandFactory scriptCommandFactory, IDatabaseContextFactory contextFactory, IMetaService metaService, - IMetaRegistration metaRegistration, IScriptPluginServiceResolver scriptPluginServiceResolver) + IMetaRegistration metaRegistration, IScriptPluginServiceResolver scriptPluginServiceResolver, ClientService clientService, IServiceProvider serviceProvider, + ChangeHistoryService changeHistoryService, ApplicationConfiguration appConfig) { MiddlewareActionHandler = actionHandler; _servers = new ConcurrentBag(); MessageTokens = new List(); - ClientSvc = new ClientService(contextFactory); + ClientSvc = clientService; AliasSvc = new AliasService(); PenaltySvc = new PenaltyService(); ConfigHandler = appConfigHandler; StartTime = DateTime.UtcNow; PageList = new PageList(); - AdditionalEventParsers = new List() { new BaseEventParser(parserRegexFactory, logger, appConfigHandler.Configuration()) }; - AdditionalRConParsers = new List() { new BaseRConParser(parserRegexFactory) }; + AdditionalEventParsers = new List() { new BaseEventParser(parserRegexFactory, logger, _appConfig) }; + AdditionalRConParsers = new List() { new BaseRConParser(serviceProvider.GetRequiredService>(), parserRegexFactory) }; TokenAuthenticator = new TokenAuthentication(); _logger = logger; _metaService = metaService; _tokenSource = new CancellationTokenSource(); - _loggers.Add(0, logger); _commands = commands.ToList(); _translationLookup = translationLookup; _commandConfiguration = commandConfiguration; @@ -102,6 +106,9 @@ namespace IW4MAdmin.Application _scriptCommandFactory = scriptCommandFactory; _metaRegistration = metaRegistration; _scriptPluginServiceResolver = scriptPluginServiceResolver; + _serviceProvider = serviceProvider; + _changeHistoryService = changeHistoryService; + _appConfig = appConfig; Plugins = plugins; } @@ -109,10 +116,6 @@ namespace IW4MAdmin.Application public async Task ExecuteEvent(GameEvent newEvent) { -#if DEBUG == true - Logger.WriteDebug($"Entering event process for {newEvent.Id}"); -#endif - // the event has failed already if (newEvent.Failed) { @@ -124,22 +127,17 @@ namespace IW4MAdmin.Application await newEvent.Owner.ExecuteEvent(newEvent); // save the event info to the database - var changeHistorySvc = new ChangeHistoryService(); - await changeHistorySvc.Add(newEvent); - -#if DEBUG - Logger.WriteDebug($"Processed event with id {newEvent.Id}"); -#endif + await _changeHistoryService.Add(newEvent); } catch (TaskCanceledException) { - Logger.WriteInfo($"Received quit signal for event id {newEvent.Id}, so we are aborting early"); + _logger.LogDebug("Received quit signal for event id {eventId}, so we are aborting early", newEvent.Id); } catch (OperationCanceledException) { - Logger.WriteInfo($"Received quit signal for event id {newEvent.Id}, so we are aborting early"); + _logger.LogDebug("Received quit signal for event id {eventId}, so we are aborting early", newEvent.Id); } // this happens if a plugin requires login @@ -152,31 +150,35 @@ namespace IW4MAdmin.Application catch (NetworkException ex) { newEvent.FailReason = EventFailReason.Exception; - Logger.WriteError(ex.Message); - Logger.WriteDebug(ex.GetExceptionInfo()); + using (LogContext.PushProperty("Server", newEvent.Owner?.ToString())) + { + _logger.LogError(ex, ex.Message); + } } catch (ServerException ex) { newEvent.FailReason = EventFailReason.Exception; - Logger.WriteWarning(ex.Message); + using (LogContext.PushProperty("Server", newEvent.Owner?.ToString())) + { + _logger.LogError(ex, ex.Message); + } } catch (Exception ex) { newEvent.FailReason = EventFailReason.Exception; - Logger.WriteError(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_EXCEPTION"].FormatExt(newEvent.Owner)); - Logger.WriteDebug(ex.GetExceptionInfo()); + Console.WriteLine(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_EXCEPTION"].FormatExt(newEvent.Owner)); + using (LogContext.PushProperty("Server", newEvent.Owner?.ToString())) + { + _logger.LogError(ex, "Unexpected exception"); + } } - skip: + skip: // tell anyone waiting for the output that we're done newEvent.Complete(); OnGameEventExecuted?.Invoke(this, newEvent); - -#if DEBUG == true - Logger.WriteDebug($"Exiting event process for {newEvent.Id}"); -#endif } public IList GetServers() @@ -226,17 +228,14 @@ namespace IW4MAdmin.Application try { await server.ProcessUpdatesAsync(_tokenSource.Token); - - if (server.Throttled) - { - await Task.Delay((int)_throttleTimeout.TotalMilliseconds, _tokenSource.Token); - } } catch (Exception e) { - Logger.WriteWarning($"Failed to update status for {server}"); - Logger.WriteDebug(e.GetExceptionInfo()); + using (LogContext.PushProperty("Server", server.ToString())) + { + _logger.LogError(e, "Failed to update status"); + } } finally @@ -245,12 +244,7 @@ namespace IW4MAdmin.Application } })); } -#if DEBUG - Logger.WriteDebug($"{runningUpdateTasks.Count} servers queued for stats updates"); - ThreadPool.GetMaxThreads(out int workerThreads, out int n); - ThreadPool.GetAvailableThreads(out int availableThreads, out int m); - Logger.WriteDebug($"There are {workerThreads - availableThreads} active threading tasks"); -#endif + try { await Task.Delay(ConfigHandler.Configuration().RConPollRate, _tokenSource.Token); @@ -289,8 +283,8 @@ namespace IW4MAdmin.Application catch (Exception ex) { - Logger.WriteError(Utilities.CurrentLocalization.LocalizationIndex["PLUGIN_IMPORTER_ERROR"].FormatExt(scriptPlugin.Name)); - Logger.WriteDebug(ex.Message); + Console.WriteLine(Utilities.CurrentLocalization.LocalizationIndex["PLUGIN_IMPORTER_ERROR"].FormatExt(scriptPlugin.Name)); + _logger.LogError(ex, "Could not properly load plugin {plugin}", scriptPlugin.Name); } }; } @@ -303,32 +297,29 @@ namespace IW4MAdmin.Application catch (Exception ex) { - Logger.WriteError($"{_translationLookup["SERVER_ERROR_PLUGIN"]} {plugin.Name}"); - Logger.WriteDebug(ex.GetExceptionInfo()); + _logger.LogError(ex, $"{_translationLookup["SERVER_ERROR_PLUGIN"]} {plugin.Name}"); } } #endregion #region CONFIG - var config = ConfigHandler.Configuration(); - // copy over default config if it doesn't exist - if (config == null) + if (!_appConfig.Servers?.Any() ?? true) { var defaultConfig = new BaseConfigurationHandler("DefaultSettings").Configuration(); - ConfigHandler.Set((ApplicationConfiguration)new ApplicationConfiguration().Generate()); - var newConfig = ConfigHandler.Configuration(); + //ConfigHandler.Set((ApplicationConfiguration)new ApplicationConfiguration().Generate()); + //var newConfig = ConfigHandler.Configuration(); - newConfig.AutoMessages = defaultConfig.AutoMessages; - newConfig.GlobalRules = defaultConfig.GlobalRules; - newConfig.Maps = defaultConfig.Maps; - newConfig.DisallowedClientNames = defaultConfig.DisallowedClientNames; - newConfig.QuickMessages = defaultConfig.QuickMessages; + _appConfig.AutoMessages = defaultConfig.AutoMessages; + _appConfig.GlobalRules = defaultConfig.GlobalRules; + _appConfig.Maps = defaultConfig.Maps; + _appConfig.DisallowedClientNames = defaultConfig.DisallowedClientNames; + _appConfig.QuickMessages = defaultConfig.QuickMessages; - if (newConfig.Servers == null) + //if (newConfig.Servers == null) { - ConfigHandler.Set(newConfig); - newConfig.Servers = new ServerConfiguration[1]; + ConfigHandler.Set(_appConfig); + _appConfig.Servers = new ServerConfiguration[1]; do { @@ -343,30 +334,29 @@ namespace IW4MAdmin.Application serverConfig.AddEventParser(parser); } - newConfig.Servers = newConfig.Servers.Where(_servers => _servers != null).Append((ServerConfiguration)serverConfig.Generate()).ToArray(); + _appConfig.Servers = _appConfig.Servers.Where(_servers => _servers != null).Append((ServerConfiguration)serverConfig.Generate()).ToArray(); } while (Utilities.PromptBool(_translationLookup["SETUP_SERVER_SAVE"])); - config = newConfig; await ConfigHandler.Save(); } } else { - if (string.IsNullOrEmpty(config.Id)) + if (string.IsNullOrEmpty(_appConfig.Id)) { - config.Id = Guid.NewGuid().ToString(); + _appConfig.Id = Guid.NewGuid().ToString(); await ConfigHandler.Save(); } - if (string.IsNullOrEmpty(config.WebfrontBindUrl)) + if (string.IsNullOrEmpty(_appConfig.WebfrontBindUrl)) { - config.WebfrontBindUrl = "http://0.0.0.0:1624"; + _appConfig.WebfrontBindUrl = "http://0.0.0.0:1624"; await ConfigHandler.Save(); } var validator = new ApplicationConfigurationValidator(); - var validationResult = validator.Validate(config); + var validationResult = validator.Validate(_appConfig); if (!validationResult.IsValid) { @@ -377,7 +367,7 @@ namespace IW4MAdmin.Application }; } - foreach (var serverConfig in config.Servers) + foreach (var serverConfig in _appConfig.Servers) { Migration.ConfigurationMigration.ModifyLogPath020919(serverConfig); @@ -399,13 +389,13 @@ namespace IW4MAdmin.Application } } - if (config.Servers.Length == 0) + if (_appConfig.Servers.Length == 0) { throw new ServerException("A server configuration in IW4MAdminSettings.json is invalid"); } Encoding.RegisterProvider(CodePagesEncodingProvider.Instance); - Utilities.EncodingType = Encoding.GetEncoding(!string.IsNullOrEmpty(config.CustomParserEncoding) ? config.CustomParserEncoding : "windows-1252"); + Utilities.EncodingType = Encoding.GetEncoding(!string.IsNullOrEmpty(_appConfig.CustomParserEncoding) ? _appConfig.CustomParserEncoding : "windows-1252"); #endregion @@ -440,8 +430,8 @@ namespace IW4MAdmin.Application // this is because I want to store the command prefix in IW4MAdminSettings, but can't easily // inject it to all the places that need it - cmdConfig.CommandPrefix = config.CommandPrefix; - cmdConfig.BroadcastCommandPrefix = config.BroadcastCommandPrefix; + cmdConfig.CommandPrefix = _appConfig.CommandPrefix; + cmdConfig.BroadcastCommandPrefix = _appConfig.BroadcastCommandPrefix; foreach (var cmd in commandsToAddToConfig) { @@ -472,6 +462,7 @@ namespace IW4MAdmin.Application } #endregion + Console.WriteLine(_translationLookup["MANAGER_COMMUNICATION_INFO"]); await InitializeServers(); } @@ -487,13 +478,17 @@ namespace IW4MAdmin.Application { // todo: this might not always be an IW4MServer var ServerInstance = _serverInstanceFactory.CreateServer(Conf, this) as IW4MServer; - await ServerInstance.Initialize(); + using (LogContext.PushProperty("Server", ServerInstance.ToString())) + { + _logger.LogInformation("Beginning server communication initialization"); + await ServerInstance.Initialize(); - _servers.Add(ServerInstance); + _servers.Add(ServerInstance); + Console.WriteLine(Utilities.CurrentLocalization.LocalizationIndex["MANAGER_MONITORING_TEXT"].FormatExt(ServerInstance.Hostname.StripColors())); + _logger.LogInformation("Finishing initialization and now monitoring [{server}]", ServerInstance.Hostname, ServerInstance.ToString()); + } - Logger.WriteVerbose(Utilities.CurrentLocalization.LocalizationIndex["MANAGER_MONITORING_TEXT"].FormatExt(ServerInstance.Hostname)); // add the start event for this server - var e = new GameEvent() { Type = GameEvent.EventType.Start, @@ -507,13 +502,11 @@ namespace IW4MAdmin.Application catch (ServerException e) { - Logger.WriteError(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_UNFIXABLE"].FormatExt($"[{Conf.IPAddress}:{Conf.Port}]")); - - if (e.GetType() == typeof(DvarException)) + Console.WriteLine(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_UNFIXABLE"].FormatExt($"[{Conf.IPAddress}:{Conf.Port}]")); + using (LogContext.PushProperty("Server", $"{Conf.IPAddress}:{Conf.Port}")) { - Logger.WriteDebug($"{e.Message} {(e.GetType() == typeof(DvarException) ? $"({Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_DVAR_HELP"]})" : "")}"); + _logger.LogError(e, "Unexpected exception occurred during initialization"); } - lastException = e; } } @@ -548,20 +541,10 @@ namespace IW4MAdmin.Application Stop(); } - public ILogger GetLogger(long serverId) + [Obsolete] + public ObsoleteLogger GetLogger(long serverId) { - if (_loggers.ContainsKey(serverId)) - { - return _loggers[serverId]; - } - - else - { - var newLogger = new Logger($"IW4MAdmin-Server-{serverId}"); - - _loggers.Add(serverId, newLogger); - return newLogger; - } + return _serviceProvider.GetRequiredService(); } public IList GetMessageTokens() @@ -607,7 +590,7 @@ namespace IW4MAdmin.Application public IRConParser GenerateDynamicRConParser(string name) { - return new DynamicRConParser(_parserRegexFactory) + return new DynamicRConParser(_serviceProvider.GetRequiredService>(), _parserRegexFactory) { Name = name }; diff --git a/Application/BuildScripts/PostBuild.bat b/Application/BuildScripts/PostBuild.bat index 6433f9de2..c3cbc996c 100644 --- a/Application/BuildScripts/PostBuild.bat +++ b/Application/BuildScripts/PostBuild.bat @@ -4,24 +4,13 @@ set TargetDir=%3 set OutDir=%4 set Version=%5 -echo %Version% > "%SolutionDir%DEPLOY\version.txt" - echo Copying dependency configs copy "%SolutionDir%WebfrontCore\%OutDir%*.deps.json" "%TargetDir%" -copy "%SolutionDir%SharedLibaryCore\%OutDir%*.deps.json" "%TargetDir%" +copy "%SolutionDir%SharedLibraryCore\%OutDir%*.deps.json" "%TargetDir%" if not exist "%TargetDir%Plugins" ( echo "Making plugin dir" md "%TargetDir%Plugins" ) -xcopy /y "%SolutionDir%Build\Plugins" "%TargetDir%Plugins\" - -echo Copying plugins for publish -del %SolutionDir%BUILD\Plugins\Tests.dll -xcopy /Y "%SolutionDir%BUILD\Plugins" "%SolutionDir%Publish\Windows\Plugins\" -xcopy /Y "%SolutionDir%BUILD\Plugins" "%SolutionDir%Publish\WindowsPrerelease\Plugins\" - -echo Copying script plugins for publish -xcopy /Y "%SolutionDir%Plugins\ScriptPlugins" "%SolutionDir%Publish\Windows\Plugins\" -xcopy /Y "%SolutionDir%Plugins\ScriptPlugins" "%SolutionDir%Publish\WindowsPrerelease\Plugins\" \ No newline at end of file +xcopy /y "%SolutionDir%Build\Plugins" "%TargetDir%Plugins\" \ No newline at end of file diff --git a/Application/Configuration/LoggingConfiguration.json b/Application/Configuration/LoggingConfiguration.json new file mode 100644 index 000000000..9c4bd9fc6 --- /dev/null +++ b/Application/Configuration/LoggingConfiguration.json @@ -0,0 +1,43 @@ +{ + "Serilog": { + "Using": [ + "Serilog.Sinks.File" + ], + "MinimumLevel": "Information", + "WriteTo": [ + { + "Name": "File", + "Args": { + "path": "Log/IW4MAdmin-Application.log", + "rollingInterval": "Day", + "outputTemplate": "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff} {Server} {Level:u3}] {Message:lj}{NewLine}{Exception}" + } + } + ], + "Enrich": [ + "FromLogContext", + "WithMachineName", + "WithThreadId" + ], + "Destructure": [ + { + "Name": "ToMaximumDepth", + "Args": { + "maximumDestructuringDepth": 4 + } + }, + { + "Name": "ToMaximumStringLength", + "Args": { + "maximumStringLength": 1000 + } + }, + { + "Name": "ToMaximumCollectionCount", + "Args": { + "maximumCollectionCount": 24 + } + } + ] + } +} \ No newline at end of file diff --git a/Application/EventParsers/BaseEventParser.cs b/Application/EventParsers/BaseEventParser.cs index a786628ea..1d81f3081 100644 --- a/Application/EventParsers/BaseEventParser.cs +++ b/Application/EventParsers/BaseEventParser.cs @@ -5,7 +5,9 @@ using SharedLibraryCore.Interfaces; using System; using System.Collections.Generic; using System.Linq; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.Server; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.EventParsers { @@ -348,7 +350,7 @@ namespace IW4MAdmin.Application.EventParsers catch (Exception e) { - _logger.WriteWarning($"Could not handle custom event generation - {e.GetExceptionInfo()}"); + _logger.LogError(e, $"Could not handle custom event generation"); } } diff --git a/Application/EventParsers/DynamicEventParser.cs b/Application/EventParsers/DynamicEventParser.cs index 17022320a..8c8c0fb33 100644 --- a/Application/EventParsers/DynamicEventParser.cs +++ b/Application/EventParsers/DynamicEventParser.cs @@ -1,5 +1,6 @@ using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.EventParsers { diff --git a/Application/Extensions/StartupExtensions.cs b/Application/Extensions/StartupExtensions.cs new file mode 100644 index 000000000..614cd2fe5 --- /dev/null +++ b/Application/Extensions/StartupExtensions.cs @@ -0,0 +1,41 @@ +using System.IO; +using Microsoft.Extensions.Configuration; +using Microsoft.Extensions.DependencyInjection; +using Serilog; +using SharedLibraryCore; +using SharedLibraryCore.Configuration; + +namespace IW4MAdmin.Application.Extensions +{ + public static class StartupExtensions + { + private static ILogger _defaultLogger = null; + + public static IServiceCollection AddBaseLogger(this IServiceCollection services, + ApplicationConfiguration appConfig) + { + if (_defaultLogger == null) + { + var configuration = new ConfigurationBuilder() + .AddJsonFile(Path.Join(Utilities.OperatingDirectory, "Configuration", "LoggingConfiguration.json")) + .Build(); + + var loggerConfig = new LoggerConfiguration() + .ReadFrom.Configuration(configuration); + + + if (Utilities.IsDevelopment) + { + loggerConfig = loggerConfig.WriteTo.Console( + outputTemplate:"[{Timestamp:yyyy-MM-dd HH:mm:ss.fff} {Server} {Level:u3}] {Message:lj}{NewLine}{Exception}") + .MinimumLevel.Debug(); + } + + _defaultLogger = loggerConfig.CreateLogger(); + } + + services.AddLogging(builder => builder.AddSerilog(_defaultLogger, dispose: true)); + return services; + } + } +} \ No newline at end of file diff --git a/Application/Factories/GameLogReaderFactory.cs b/Application/Factories/GameLogReaderFactory.cs index 53854e8b0..e035e012b 100644 --- a/Application/Factories/GameLogReaderFactory.cs +++ b/Application/Factories/GameLogReaderFactory.cs @@ -2,6 +2,7 @@ using Microsoft.Extensions.DependencyInjection; using SharedLibraryCore.Interfaces; using System; +using Microsoft.Extensions.Logging; namespace IW4MAdmin.Application.Factories { @@ -19,12 +20,12 @@ namespace IW4MAdmin.Application.Factories var baseUri = logUris[0]; if (baseUri.Scheme == Uri.UriSchemeHttp) { - return new GameLogReaderHttp(logUris, eventParser, _serviceProvider.GetRequiredService()); + return new GameLogReaderHttp(logUris, eventParser, _serviceProvider.GetRequiredService>()); } else if (baseUri.Scheme == Uri.UriSchemeFile) { - return new GameLogReader(baseUri.LocalPath, eventParser, _serviceProvider.GetRequiredService()); + return new GameLogReader(baseUri.LocalPath, eventParser, _serviceProvider.GetRequiredService>()); } throw new NotImplementedException($"No log reader implemented for Uri scheme \"{baseUri.Scheme}\""); diff --git a/Application/Factories/GameServerInstanceFactory.cs b/Application/Factories/GameServerInstanceFactory.cs index 97a532579..9e91d54b7 100644 --- a/Application/Factories/GameServerInstanceFactory.cs +++ b/Application/Factories/GameServerInstanceFactory.cs @@ -1,7 +1,7 @@ -using SharedLibraryCore; +using System; +using SharedLibraryCore; using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; -using System.Collections; namespace IW4MAdmin.Application.Factories { @@ -11,21 +11,21 @@ namespace IW4MAdmin.Application.Factories internal class GameServerInstanceFactory : IGameServerInstanceFactory { private readonly ITranslationLookup _translationLookup; - private readonly IRConConnectionFactory _rconConnectionFactory; - private readonly IGameLogReaderFactory _gameLogReaderFactory; private readonly IMetaService _metaService; + private readonly IServiceProvider _serviceProvider; /// /// base constructor /// /// /// - public GameServerInstanceFactory(ITranslationLookup translationLookup, IRConConnectionFactory rconConnectionFactory, IGameLogReaderFactory gameLogReaderFactory, IMetaService metaService) + public GameServerInstanceFactory(ITranslationLookup translationLookup, + IMetaService metaService, + IServiceProvider serviceProvider) { _translationLookup = translationLookup; - _rconConnectionFactory = rconConnectionFactory; - _gameLogReaderFactory = gameLogReaderFactory; _metaService = metaService; + _serviceProvider = serviceProvider; } /// @@ -36,7 +36,7 @@ namespace IW4MAdmin.Application.Factories /// public Server CreateServer(ServerConfiguration config, IManager manager) { - return new IW4MServer(manager, config, _translationLookup, _rconConnectionFactory, _gameLogReaderFactory, _metaService); + return new IW4MServer(config, _translationLookup, _metaService, _serviceProvider); } } } diff --git a/Application/Factories/RConConnectionFactory.cs b/Application/Factories/RConConnectionFactory.cs index 1dd0d2f88..b65d2b4b4 100644 --- a/Application/Factories/RConConnectionFactory.cs +++ b/Application/Factories/RConConnectionFactory.cs @@ -1,6 +1,7 @@ using IW4MAdmin.Application.RCon; using SharedLibraryCore.Interfaces; using System.Text; +using Microsoft.Extensions.Logging; namespace IW4MAdmin.Application.Factories { @@ -10,13 +11,13 @@ namespace IW4MAdmin.Application.Factories internal class RConConnectionFactory : IRConConnectionFactory { private static readonly Encoding gameEncoding = Encoding.GetEncoding("windows-1252"); - private readonly ILogger _logger; + private readonly ILogger _logger; /// /// Base constructor /// /// - public RConConnectionFactory(ILogger logger) + public RConConnectionFactory(ILogger logger) { _logger = logger; } diff --git a/Application/Factories/ScriptCommandFactory.cs b/Application/Factories/ScriptCommandFactory.cs index 8b6091444..d2e3a38bb 100644 --- a/Application/Factories/ScriptCommandFactory.cs +++ b/Application/Factories/ScriptCommandFactory.cs @@ -6,6 +6,8 @@ using SharedLibraryCore.Interfaces; using System; using System.Collections.Generic; using System.Linq; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.Database.Models.EFClient; namespace IW4MAdmin.Application.Factories @@ -15,17 +17,20 @@ namespace IW4MAdmin.Application.Factories /// public class ScriptCommandFactory : IScriptCommandFactory { - private CommandConfiguration _config; + private readonly CommandConfiguration _config; private readonly ITranslationLookup _transLookup; + private readonly IServiceProvider _serviceProvider; - public ScriptCommandFactory(CommandConfiguration config, ITranslationLookup transLookup) + public ScriptCommandFactory(CommandConfiguration config, ITranslationLookup transLookup, IServiceProvider serviceProvider) { _config = config; _transLookup = transLookup; + _serviceProvider = serviceProvider; } /// - public IManagerCommand CreateScriptCommand(string name, string alias, string description, string permission, bool isTargetRequired, IEnumerable<(string, bool)> args, Action executeAction) + public IManagerCommand CreateScriptCommand(string name, string alias, string description, string permission, + bool isTargetRequired, IEnumerable<(string, bool)> args, Action executeAction) { var permissionEnum = Enum.Parse(permission); var argsArray = args.Select(_arg => new CommandArgument @@ -34,7 +39,8 @@ namespace IW4MAdmin.Application.Factories Required = _arg.Item2 }).ToArray(); - return new ScriptCommand(name, alias, description, isTargetRequired, permissionEnum, argsArray, executeAction, _config, _transLookup); + return new ScriptCommand(name, alias, description, isTargetRequired, permissionEnum, argsArray, executeAction, + _config, _transLookup, _serviceProvider.GetRequiredService>()); } } } diff --git a/Application/GameEventHandler.cs b/Application/GameEventHandler.cs index 1dfc52829..45ccf8ddf 100644 --- a/Application/GameEventHandler.cs +++ b/Application/GameEventHandler.cs @@ -1,19 +1,18 @@ using IW4MAdmin.Application.Misc; -using Newtonsoft.Json; using SharedLibraryCore; using SharedLibraryCore.Events; using SharedLibraryCore.Interfaces; -using System; -using System.Collections.Generic; using System.Linq; -using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application { public class GameEventHandler : IEventHandler { private readonly EventLog _eventLog; + private readonly ILogger _logger; private static readonly GameEvent.EventType[] overrideEvents = new[] { GameEvent.EventType.Connect, @@ -22,34 +21,23 @@ namespace IW4MAdmin.Application GameEvent.EventType.Stop }; - public GameEventHandler() + public GameEventHandler(ILogger logger) { _eventLog = new EventLog(); + _logger = logger; } public void HandleEvent(IManager manager, GameEvent gameEvent) { -#if DEBUG - ThreadPool.GetMaxThreads(out int workerThreads, out int n); - ThreadPool.GetAvailableThreads(out int availableThreads, out int m); - gameEvent.Owner.Logger.WriteDebug($"There are {workerThreads - availableThreads} active threading tasks"); - -#endif if (manager.IsRunning || overrideEvents.Contains(gameEvent.Type)) { -#if DEBUG - gameEvent.Owner.Logger.WriteDebug($"Adding event with id {gameEvent.Id}"); -#endif - EventApi.OnGameEvent(gameEvent); Task.Factory.StartNew(() => manager.ExecuteEvent(gameEvent)); } -#if DEBUG else { - gameEvent.Owner.Logger.WriteDebug($"Skipping event as we're shutting down {gameEvent.Id}"); + _logger.LogDebug("Skipping event as we're shutting down {eventId}", gameEvent.Id); } -#endif } } } diff --git a/Application/IO/GameLogEventDetection.cs b/Application/IO/GameLogEventDetection.cs index be9468a89..9a9a1f0b2 100644 --- a/Application/IO/GameLogEventDetection.cs +++ b/Application/IO/GameLogEventDetection.cs @@ -3,6 +3,9 @@ using SharedLibraryCore.Interfaces; using System; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.IO { @@ -12,12 +15,14 @@ namespace IW4MAdmin.Application.IO private readonly Server _server; private readonly IGameLogReader _reader; private readonly bool _ignoreBots; + private readonly ILogger _logger; - public GameLogEventDetection(Server server, Uri[] gameLogUris, IGameLogReaderFactory gameLogReaderFactory) + public GameLogEventDetection(ILogger logger, Server server, Uri[] gameLogUris, IGameLogReaderFactory gameLogReaderFactory) { _reader = gameLogReaderFactory.CreateGameLogReader(gameLogUris, server.EventParser); _server = server; _ignoreBots = server?.Manager.GetApplicationSettings().Configuration().IgnoreBots ?? false; + _logger = logger; } public async Task PollForChanges() @@ -33,15 +38,17 @@ namespace IW4MAdmin.Application.IO catch (Exception e) { - _server.Logger.WriteWarning($"Failed to update log event for {_server.EndPoint}"); - _server.Logger.WriteDebug(e.GetExceptionInfo()); + using(LogContext.PushProperty("Server", _server.ToString())) + { + _logger.LogError(e, "Failed to update log event for {endpoint}", _server.EndPoint); + } } } await Task.Delay(_reader.UpdateInterval, _server.Manager.CancellationToken); } - _server.Logger.WriteDebug("Stopped polling for changes"); + _logger.LogDebug("Stopped polling for changes"); } public async Task UpdateLogEvents() @@ -68,9 +75,6 @@ namespace IW4MAdmin.Application.IO { try { -#if DEBUG - _server.Logger.WriteVerbose(gameEvent.Data); -#endif gameEvent.Owner = _server; // we don't want to add the event if ignoreBots is on and the event comes from a bot @@ -102,10 +106,14 @@ namespace IW4MAdmin.Application.IO catch (InvalidOperationException) { - if (!_ignoreBots) + if (_ignoreBots) { - _server.Logger.WriteWarning("Could not find client in client list when parsing event line"); - _server.Logger.WriteDebug(gameEvent.Data); + continue; + } + + using(LogContext.PushProperty("Server", _server.ToString())) + { + _logger.LogError("Could not find client in client list when parsing event line {data}", gameEvent.Data); } } } diff --git a/Application/IO/GameLogReader.cs b/Application/IO/GameLogReader.cs index 764de90a7..d1339cd9f 100644 --- a/Application/IO/GameLogReader.cs +++ b/Application/IO/GameLogReader.cs @@ -6,6 +6,8 @@ using System.IO; using System.Linq; using System.Text; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.IO { @@ -19,7 +21,7 @@ namespace IW4MAdmin.Application.IO public int UpdateInterval => 300; - public GameLogReader(string logFile, IEventParser parser, ILogger logger) + public GameLogReader(string logFile, IEventParser parser, ILogger logger) { _logFile = logFile; _parser = parser; @@ -73,9 +75,7 @@ namespace IW4MAdmin.Application.IO catch (Exception e) { - _logger.WriteWarning("Could not properly parse event line"); - _logger.WriteDebug(e.Message); - _logger.WriteDebug(eventLine); + _logger.LogError(e, "Could not properly parse event line {@eventLine}", eventLine); } } diff --git a/Application/IO/GameLogReaderHttp.cs b/Application/IO/GameLogReaderHttp.cs index 822861d0f..5662593e1 100644 --- a/Application/IO/GameLogReaderHttp.cs +++ b/Application/IO/GameLogReaderHttp.cs @@ -6,6 +6,8 @@ using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.IO { @@ -20,7 +22,7 @@ namespace IW4MAdmin.Application.IO private readonly string _safeLogPath; private string lastKey = "next"; - public GameLogReaderHttp(Uri[] gameLogServerUris, IEventParser parser, ILogger logger) + public GameLogReaderHttp(Uri[] gameLogServerUris, IEventParser parser, ILogger logger) { _eventParser = parser; _logServerApi = RestClient.For(gameLogServerUris[0].ToString()); @@ -40,7 +42,7 @@ namespace IW4MAdmin.Application.IO if (!response.Success && string.IsNullOrEmpty(lastKey)) { - _logger.WriteError($"Could not get log server info of {_safeLogPath}"); + _logger.LogError("Could not get log server info of {logPath}", _safeLogPath); return events; } @@ -62,9 +64,7 @@ namespace IW4MAdmin.Application.IO catch (Exception e) { - _logger.WriteError("Could not properly parse event line from http"); - _logger.WriteDebug(e.Message); - _logger.WriteDebug(eventLine); + _logger.LogError(e, "Could not properly parse event line from http {eventLine}", eventLine); } } } diff --git a/Application/IW4MServer.cs b/Application/IW4MServer.cs index f3f8de0c5..26e0fecb7 100644 --- a/Application/IW4MServer.cs +++ b/Application/IW4MServer.cs @@ -12,10 +12,12 @@ using System.Collections.Generic; using System.IO; using System.Linq; using System.Runtime.InteropServices; -using System.Text; using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Serilog.Context; using static SharedLibraryCore.Database.Models.EFClient; namespace IW4MAdmin @@ -30,37 +32,45 @@ namespace IW4MAdmin private int lastGameTime = 0; public int Id { get; private set; } + private readonly IServiceProvider _serviceProvider; - public IW4MServer(IManager mgr, ServerConfiguration cfg, ITranslationLookup lookup, - IRConConnectionFactory connectionFactory, IGameLogReaderFactory gameLogReaderFactory, IMetaService metaService) : base(cfg, mgr, connectionFactory, gameLogReaderFactory) + public IW4MServer( + ServerConfiguration serverConfiguration, + ITranslationLookup lookup, + IMetaService metaService, + IServiceProvider serviceProvider) : base(serviceProvider.GetRequiredService>(), + serviceProvider.GetRequiredService(), + serverConfiguration, + serviceProvider.GetRequiredService(), + serviceProvider.GetRequiredService(), + serviceProvider.GetRequiredService()) { _translationLookup = lookup; _metaService = metaService; + _serviceProvider = serviceProvider; } - override public async Task OnClientConnected(EFClient clientFromLog) + public override async Task OnClientConnected(EFClient clientFromLog) { - Logger.WriteDebug($"Client slot #{clientFromLog.ClientNumber} now reserved"); + ServerLogger.LogDebug("Client slot #{clientNumber} now reserved", clientFromLog.ClientNumber); EFClient client = await Manager.GetClientService().GetUnique(clientFromLog.NetworkId); // first time client is connecting to server if (client == null) { - Logger.WriteDebug($"Client {clientFromLog} first time connecting"); + ServerLogger.LogDebug("Client {client} first time connecting", clientFromLog.ToString()); clientFromLog.CurrentServer = this; client = await Manager.GetClientService().Create(clientFromLog); } - /// this is only a temporary version until the IPAddress is transmitted + // this is only a temporary version until the IPAddress is transmitted client.CurrentAlias = new EFAlias() { Name = clientFromLog.Name, IPAddress = clientFromLog.IPAddress }; - Logger.WriteInfo($"Client {client} connected..."); - // Do the player specific stuff client.ClientNumber = clientFromLog.ClientNumber; client.Score = clientFromLog.Score; @@ -69,9 +79,7 @@ namespace IW4MAdmin client.State = ClientState.Connecting; Clients[client.ClientNumber] = client; -#if DEBUG == true - Logger.WriteDebug($"End PreConnect for {client}"); -#endif + ServerLogger.LogDebug("End PreConnect for {client}", client.ToString()); var e = new GameEvent() { Origin = client, @@ -83,11 +91,14 @@ namespace IW4MAdmin return client; } - override public async Task OnClientDisconnected(EFClient client) + public override async Task OnClientDisconnected(EFClient client) { if (!GetClientsAsList().Any(_client => _client.NetworkId == client.NetworkId)) { - Logger.WriteInfo($"{client} disconnecting, but they are not connected"); + using (LogContext.PushProperty("Server", ToString())) + { + ServerLogger.LogWarning("{client} disconnecting, but they are not connected", client.ToString()); + } return; } @@ -95,7 +106,7 @@ namespace IW4MAdmin if (client.ClientNumber >= 0) { #endif - Logger.WriteInfo($"Client {client} [{client.State.ToString().ToLower()}] disconnecting..."); + ServerLogger.LogDebug("Client {@client} disconnecting...", new { client=client.ToString(), client.State }); Clients[client.ClientNumber] = null; await client.OnDisconnect(); @@ -114,124 +125,111 @@ namespace IW4MAdmin public override async Task ExecuteEvent(GameEvent E) { - if (E == null) - { - Logger.WriteError("Received NULL event"); - return; - } - - if (E.IsBlocking) - { - await E.Origin?.Lock(); - } - - bool canExecuteCommand = true; - Exception lastException = null; - - try - { - if (!await ProcessEvent(E)) - { - return; - } - - Command C = null; - if (E.Type == GameEvent.EventType.Command) - { - try - { - C = await SharedLibraryCore.Commands.CommandProcessing.ValidateCommand(E, Manager.GetApplicationSettings().Configuration()); - } - - catch (CommandException e) - { - Logger.WriteInfo(e.Message); - E.FailReason = GameEvent.EventFailReason.Invalid; - } - - if (C != null) - { - E.Extra = C; - } - } - - try - { - var loginPlugin = Manager.Plugins.FirstOrDefault(_plugin => _plugin.Name == "Login"); - - if (loginPlugin != null) - { - await loginPlugin.OnEventAsync(E, this); - } - } - - catch (AuthorizationException e) - { - E.Origin.Tell($"{loc["COMMAND_NOTAUTHORIZED"]} - {e.Message}"); - canExecuteCommand = false; - } - - // 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); - } - - var pluginTasks = Manager.Plugins.Where(_plugin => _plugin.Name != "Login").Select(async _plugin => - { - try - { - // we don't want to run the events on parser plugins - if (_plugin is ScriptPlugin scriptPlugin && scriptPlugin.IsParser) - { - return; - } - - using (var tokenSource = new CancellationTokenSource()) - { - tokenSource.CancelAfter(Utilities.DefaultCommandTimeout); - await (_plugin.OnEventAsync(E, this)).WithWaitCancellation(tokenSource.Token); - } - } - catch (Exception Except) - { - Logger.WriteError($"{loc["SERVER_PLUGIN_ERROR"]} [{_plugin.Name}]"); - Logger.WriteDebug(Except.GetExceptionInfo()); - } - }).ToArray(); - - if (pluginTasks.Any()) - { - await Task.WhenAny(pluginTasks); - } - } - - catch (Exception e) - { - lastException = e; - - if (E.Origin != null && E.Type == GameEvent.EventType.Command) - { - E.Origin.Tell(_translationLookup["SERVER_ERROR_COMMAND_INGAME"]); - } - } - - finally + using (LogContext.PushProperty("Server", ToString())) { if (E.IsBlocking) { - E.Origin?.Unlock(); + await E.Origin?.Lock(); } - if (lastException != null) + bool canExecuteCommand = true; + + try { - bool notifyDisconnects = !Manager.GetApplicationSettings().Configuration().IgnoreServerConnectionLost; - if (notifyDisconnects || (!notifyDisconnects && lastException as NetworkException == null)) + if (!await ProcessEvent(E)) { - throw lastException; + return; + } + + Command C = null; + if (E.Type == GameEvent.EventType.Command) + { + try + { + C = await SharedLibraryCore.Commands.CommandProcessing.ValidateCommand(E, Manager.GetApplicationSettings().Configuration()); + } + + catch (CommandException e) + { + ServerLogger.LogWarning(e, "Error validating command from event {@event}", E); + E.FailReason = GameEvent.EventFailReason.Invalid; + } + + if (C != null) + { + E.Extra = C; + } + } + + try + { + var loginPlugin = Manager.Plugins.FirstOrDefault(_plugin => _plugin.Name == "Login"); + + if (loginPlugin != null) + { + await loginPlugin.OnEventAsync(E, this); + } + } + + catch (AuthorizationException e) + { + E.Origin.Tell($"{loc["COMMAND_NOTAUTHORIZED"]} - {e.Message}"); + canExecuteCommand = false; + } + + // 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)) + { + ServerLogger.LogInformation("Executing command {comamnd} for {client}", command.Name, E.Origin.ToString()); + await command.ExecuteAsync(E); + } + + var pluginTasks = Manager.Plugins + .Where(_plugin => _plugin.Name != "Login") + .Select(async plugin => await CreatePluginTask(plugin, E)); + + await Task.WhenAll(pluginTasks); + } + + catch (Exception e) + { + if (E.Origin != null && E.Type == GameEvent.EventType.Command) + { + E.Origin.Tell(_translationLookup["SERVER_ERROR_COMMAND_INGAME"]); } } + + finally + { + if (E.IsBlocking) + { + E.Origin?.Unlock(); + } + } + } + } + + private async Task CreatePluginTask(IPlugin plugin, GameEvent gameEvent) + { + // we don't want to run the events on parser plugins + if (plugin is ScriptPlugin scriptPlugin && scriptPlugin.IsParser) + { + return; + } + + using var tokenSource = new CancellationTokenSource(); + tokenSource.CancelAfter(Utilities.DefaultCommandTimeout); + + try + { + await (plugin.OnEventAsync(gameEvent, this)).WithWaitCancellation(tokenSource.Token); + } + catch (Exception ex) + { + Console.WriteLine(loc["SERVER_PLUGIN_ERROR"]); + ServerLogger.LogError(ex, "Could not execute {methodName} for plugin {plugin}", + nameof(plugin.OnEventAsync), plugin.Name); } } @@ -240,403 +238,418 @@ namespace IW4MAdmin /// /// /// - override protected async Task ProcessEvent(GameEvent E) + protected override async Task ProcessEvent(GameEvent E) { -#if DEBUG - Logger.WriteDebug($"processing event of type {E.Type}"); -#endif - - if (E.Type == GameEvent.EventType.ConnectionLost) + using (LogContext.PushProperty("Server", ToString())) + using (LogContext.PushProperty("EventType", E.Type)) { - var exception = E.Extra as Exception; - if (!Manager.GetApplicationSettings().Configuration().IgnoreServerConnectionLost) + ServerLogger.LogDebug("processing event of type {type}", E.Type); + + if (E.Type == GameEvent.EventType.ConnectionLost) { - Logger.WriteError(exception.Message); - if (exception.Data["internal_exception"] != null) + var exception = E.Extra as Exception; + ServerLogger.LogError(exception, + "Connection lost with {server}", ToString()); + + if (!Manager.GetApplicationSettings().Configuration().IgnoreServerConnectionLost) { - Logger.WriteDebug($"Internal Exception: {exception.Data["internal_exception"]}"); - } - } - Logger.WriteInfo("Connection lost to server, so we are throttling the poll rate"); - Throttled = true; - } - - if (E.Type == GameEvent.EventType.ConnectionRestored) - { - if (Throttled && !Manager.GetApplicationSettings().Configuration().IgnoreServerConnectionLost) - { - Logger.WriteVerbose(loc["MANAGER_CONNECTION_REST"].FormatExt($"[{IP}:{Port}]")); - } - Logger.WriteInfo("Connection restored to server, so we are no longer throttling the poll rate"); - Throttled = false; - } - - if (E.Type == GameEvent.EventType.ChangePermission) - { - var newPermission = (Permission)E.Extra; - Logger.WriteInfo($"{E.Origin} is setting {E.Target} to permission level {newPermission}"); - 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 - if (E.Origin.IsBot && Manager.GetApplicationSettings().Configuration().IgnoreBots) - { - return false; - } - - if (E.Origin.CurrentServer == null) - { - Logger.WriteWarning($"preconnecting client {E.Origin} did not have a current server specified"); - E.Origin.CurrentServer = this; - } - - var existingClient = GetClientsAsList().FirstOrDefault(_client => _client.Equals(E.Origin)); - - // they're already connected - if (existingClient != null && existingClient.ClientNumber == E.Origin.ClientNumber && !E.Origin.IsBot) - { - Logger.WriteWarning($"detected preconnect for {E.Origin}, but they are already connected"); - return false; - } - - // this happens for some reason rarely where the client spots get out of order - // possible a connect/reconnect game event before we get to process it here - // it appears that new games decide to switch client slots between maps (even if the clients aren't disconnecting) - // bots can have duplicate names which causes conflicting GUIDs - else if (existingClient != null && existingClient.ClientNumber != E.Origin.ClientNumber && !E.Origin.IsBot) - { - Logger.WriteWarning($"client {E.Origin} is trying to connect in client slot {E.Origin.ClientNumber}, but they are already registed in client slot {existingClient.ClientNumber}, swapping..."); - // we need to remove them so the client spots can swap - await OnClientDisconnected(Clients[existingClient.ClientNumber]); - } - - if (Clients[E.Origin.ClientNumber] == null) - { -#if DEBUG == true - Logger.WriteDebug($"Begin PreConnect for {E.Origin}"); -#endif - // we can go ahead and put them in so that they don't get re added - Clients[E.Origin.ClientNumber] = E.Origin; - try - { - E.Origin = await OnClientConnected(E.Origin); - E.Target = E.Origin; + Console.WriteLine(loc["SERVER_ERROR_COMMUNICATION"].FormatExt($"{IP}:{Port}")); } - catch (Exception ex) - { - Logger.WriteError($"{loc["SERVER_ERROR_ADDPLAYER"]} {E.Origin}"); - Logger.WriteDebug(ex.GetExceptionInfo()); + Throttled = true; + } - Clients[E.Origin.ClientNumber] = null; + if (E.Type == GameEvent.EventType.ConnectionRestored) + { + ServerLogger.LogInformation( + "Connection restored with {server}", ToString()); + + if (!Manager.GetApplicationSettings().Configuration().IgnoreServerConnectionLost) + { + Console.WriteLine(loc["MANAGER_CONNECTION_REST"].FormatExt($"[{IP}:{Port}]")); + } + + Throttled = false; + } + + if (E.Type == GameEvent.EventType.ChangePermission) + { + var newPermission = (Permission) E.Extra; + ServerLogger.LogInformation("{origin} is setting {target} to permission level {newPermission}", + E.Origin.ToString(), E.Target.ToString(), newPermission); + 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) + { + ServerLogger.LogInformation("Detected PreConnect for {client} from {source}", E.Origin.ToString(), E.Source); + // we don't want to track bots in the database at all if ignore bots is requested + if (E.Origin.IsBot && Manager.GetApplicationSettings().Configuration().IgnoreBots) + { return false; } - if (E.Origin.Level > Permission.Moderator) + if (E.Origin.CurrentServer == null) { - E.Origin.Tell(string.Format(loc["SERVER_REPORT_COUNT"], E.Owner.Reports.Count)); + ServerLogger.LogWarning("Preconnecting client {client} did not have a current server specified", + E.Origin.ToString()); + E.Origin.CurrentServer = this; } - } - // for some reason there's still a client in the spot - else - { - Logger.WriteWarning($"{E.Origin} is connecting but {Clients[E.Origin.ClientNumber]} is currently in that client slot"); - } - } + var existingClient = GetClientsAsList().FirstOrDefault(_client => _client.Equals(E.Origin)); - else if (E.Type == GameEvent.EventType.Flag) - { - DateTime? expires = null; - - if (E.Extra is TimeSpan ts) - { - expires = DateTime.UtcNow + ts; - } - - // todo: maybe move this to a seperate function - var newPenalty = new EFPenalty() - { - Type = EFPenalty.PenaltyType.Flag, - Expires = expires, - Offender = E.Target, - Offense = E.Data, - Punisher = E.ImpersonationOrigin ?? E.Origin, - When = DateTime.UtcNow, - Link = E.Target.AliasLink - }; - - var addedPenalty = await Manager.GetPenaltyService().Create(newPenalty); - E.Target.SetLevel(Permission.Flagged, E.Origin); - } - - else if (E.Type == GameEvent.EventType.Unflag) - { - var unflagPenalty = new EFPenalty() - { - Type = EFPenalty.PenaltyType.Unflag, - Expires = DateTime.UtcNow, - Offender = E.Target, - Offense = E.Data, - Punisher = E.ImpersonationOrigin ?? E.Origin, - When = DateTime.UtcNow, - Link = E.Target.AliasLink - }; - - E.Target.SetLevel(Permission.User, E.Origin); - await Manager.GetPenaltyService().RemoveActivePenalties(E.Target.AliasLinkId); - await Manager.GetPenaltyService().Create(unflagPenalty); - } - - else if (E.Type == GameEvent.EventType.Report) - { - Reports.Add(new Report() - { - Origin = E.Origin, - Target = E.Target, - Reason = E.Data - }); - - var newReport = new EFPenalty() - { - Type = EFPenalty.PenaltyType.Report, - Expires = DateTime.UtcNow, - Offender = E.Target, - Offense = E.Message, - Punisher = E.ImpersonationOrigin ?? E.Origin, - Active = true, - When = DateTime.UtcNow, - Link = E.Target.AliasLink - }; - - await Manager.GetPenaltyService().Create(newReport); - - int reportNum = await Manager.GetClientService().GetClientReportCount(E.Target.ClientId); - bool isAutoFlagged = await Manager.GetClientService().IsAutoFlagged(E.Target.ClientId); - - if (!E.Target.IsPrivileged() && reportNum >= REPORT_FLAG_COUNT && !isAutoFlagged) - { - E.Target.Flag(Utilities.CurrentLocalization.LocalizationIndex["SERVER_AUTO_FLAG_REPORT"].FormatExt(reportNum), Utilities.IW4MAdminClient(E.Owner)); - } - } - - else if (E.Type == GameEvent.EventType.TempBan) - { - await TempBan(E.Data, (TimeSpan)E.Extra, E.Target, E.ImpersonationOrigin ?? E.Origin); ; - } - - else if (E.Type == GameEvent.EventType.Ban) - { - bool isEvade = E.Extra != null ? (bool)E.Extra : false; - await Ban(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin, isEvade); - } - - else if (E.Type == GameEvent.EventType.Unban) - { - await Unban(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin); - } - - else if (E.Type == GameEvent.EventType.Kick) - { - await Kick(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin); - } - - else if (E.Type == GameEvent.EventType.Warn) - { - await Warn(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin); - } - - else if (E.Type == GameEvent.EventType.Disconnect) - { - ChatHistory.Add(new ChatInfo() - { - Name = E.Origin.Name, - Message = "DISCONNECTED", - Time = DateTime.UtcNow - }); - - await _metaService.AddPersistentMeta("LastMapPlayed", CurrentMap.Alias, E.Origin); - await _metaService.AddPersistentMeta("LastServerPlayed", E.Owner.Hostname, E.Origin); - } - - else if (E.Type == GameEvent.EventType.PreDisconnect) - { - bool isPotentialFalseQuit = E.GameTime.HasValue && E.GameTime.Value == lastGameTime; - - if (isPotentialFalseQuit) - { - Logger.WriteInfo($"Receive predisconnect event for {E.Origin}, but it occured at game time {E.GameTime.Value}, which is the same last map change, so we're ignoring"); - return false; - } - - // predisconnect comes from minimal rcon polled players and minimal log players - // so we need to disconnect the "full" version of the client - var client = GetClientsAsList().FirstOrDefault(_client => _client.Equals(E.Origin)); - - if (client == null) - { - Logger.WriteWarning($"Client {E.Origin} detected as disconnecting, but could not find them in the player list"); - return false; - } - - else if (client.State != ClientState.Unknown) - { -#if DEBUG == true - Logger.WriteDebug($"Begin PreDisconnect for {client}"); -#endif - await OnClientDisconnected(client); -#if DEBUG == true - Logger.WriteDebug($"End PreDisconnect for {client}"); -#endif - return true; - } - - else - { - Logger.WriteWarning($"Expected disconnecting client {client} to be in state {ClientState.Connected.ToString()}, but is in state {client.State}"); - return false; - } - } - - else if (E.Type == GameEvent.EventType.Update) - { -#if DEBUG == true - Logger.WriteDebug($"Begin Update for {E.Origin}"); -#endif - await OnClientUpdate(E.Origin); - } - - if (E.Type == GameEvent.EventType.Say) - { - if (E.Data?.Length > 0) - { - string message = E.Data; - if (E.Data.IsQuickMessage()) + // they're already connected + if (existingClient != null && existingClient.ClientNumber == E.Origin.ClientNumber && + !E.Origin.IsBot) { + ServerLogger.LogInformation("{client} is already connected, so we are ignoring their PreConnect", + E.Origin.ToString()); + return false; + } + + // this happens for some reason rarely where the client spots get out of order + // possible a connect/reconnect game event before we get to process it here + // it appears that new games decide to switch client slots between maps (even if the clients aren't disconnecting) + // bots can have duplicate names which causes conflicting GUIDs + else if (existingClient != null && existingClient.ClientNumber != E.Origin.ClientNumber && + !E.Origin.IsBot) + { + ServerLogger.LogWarning( + "client {client} is trying to connect in client slot {newClientSlot}, but they are already registered in client slot {oldClientSlot}, swapping...", + E.Origin.ToString(), E.Origin.ClientNumber, existingClient.ClientNumber); + // we need to remove them so the client spots can swap + await OnClientDisconnected(Clients[existingClient.ClientNumber]); + } + + if (Clients[E.Origin.ClientNumber] == null) + { + ServerLogger.LogDebug("Begin PreConnect for {origin}", E.Origin.ToString()); + // we can go ahead and put them in so that they don't get re added + Clients[E.Origin.ClientNumber] = E.Origin; try { - message = Manager.GetApplicationSettings().Configuration() - .QuickMessages - .First(_qm => _qm.Game == GameName) - .Messages[E.Data.Substring(1)]; + E.Origin = await OnClientConnected(E.Origin); + E.Target = E.Origin; } - catch + + catch (Exception ex) { - message = E.Data.Substring(1); + Console.WriteLine($"{loc["SERVER_ERROR_ADDPLAYER"]} {E.Origin}"); + ServerLogger.LogError(ex, "Could not add player {player}", E.Origin.ToString()); + Clients[E.Origin.ClientNumber] = null; + return false; + } + + if (E.Origin.Level > Permission.Moderator) + { + E.Origin.Tell(string.Format(loc["SERVER_REPORT_COUNT"], E.Owner.Reports.Count)); } } + // for some reason there's still a client in the spot + else + { + ServerLogger.LogWarning( + "{origin} is connecting but {existingClient} is currently in that client slot", + E.Origin.ToString(), Clients[E.Origin.ClientNumber].ToString()); + } + } + + else if (E.Type == GameEvent.EventType.Flag) + { + DateTime? expires = null; + + if (E.Extra is TimeSpan ts) + { + expires = DateTime.UtcNow + ts; + } + + // todo: maybe move this to a seperate function + var newPenalty = new EFPenalty() + { + Type = EFPenalty.PenaltyType.Flag, + Expires = expires, + Offender = E.Target, + Offense = E.Data, + Punisher = E.ImpersonationOrigin ?? E.Origin, + When = DateTime.UtcNow, + Link = E.Target.AliasLink + }; + + var addedPenalty = await Manager.GetPenaltyService().Create(newPenalty); + E.Target.SetLevel(Permission.Flagged, E.Origin); + } + + else if (E.Type == GameEvent.EventType.Unflag) + { + var unflagPenalty = new EFPenalty() + { + Type = EFPenalty.PenaltyType.Unflag, + Expires = DateTime.UtcNow, + Offender = E.Target, + Offense = E.Data, + Punisher = E.ImpersonationOrigin ?? E.Origin, + When = DateTime.UtcNow, + Link = E.Target.AliasLink + }; + + E.Target.SetLevel(Permission.User, E.Origin); + await Manager.GetPenaltyService().RemoveActivePenalties(E.Target.AliasLinkId); + await Manager.GetPenaltyService().Create(unflagPenalty); + } + + else if (E.Type == GameEvent.EventType.Report) + { + Reports.Add(new Report() + { + Origin = E.Origin, + Target = E.Target, + Reason = E.Data + }); + + var newReport = new EFPenalty() + { + Type = EFPenalty.PenaltyType.Report, + Expires = DateTime.UtcNow, + Offender = E.Target, + Offense = E.Message, + Punisher = E.ImpersonationOrigin ?? E.Origin, + Active = true, + When = DateTime.UtcNow, + Link = E.Target.AliasLink + }; + + await Manager.GetPenaltyService().Create(newReport); + + int reportNum = await Manager.GetClientService().GetClientReportCount(E.Target.ClientId); + bool isAutoFlagged = await Manager.GetClientService().IsAutoFlagged(E.Target.ClientId); + + if (!E.Target.IsPrivileged() && reportNum >= REPORT_FLAG_COUNT && !isAutoFlagged) + { + E.Target.Flag( + Utilities.CurrentLocalization.LocalizationIndex["SERVER_AUTO_FLAG_REPORT"] + .FormatExt(reportNum), Utilities.IW4MAdminClient(E.Owner)); + } + } + + else if (E.Type == GameEvent.EventType.TempBan) + { + await TempBan(E.Data, (TimeSpan) E.Extra, E.Target, E.ImpersonationOrigin ?? E.Origin); + ; + } + + else if (E.Type == GameEvent.EventType.Ban) + { + bool isEvade = E.Extra != null ? (bool) E.Extra : false; + await Ban(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin, isEvade); + } + + else if (E.Type == GameEvent.EventType.Unban) + { + await Unban(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin); + } + + else if (E.Type == GameEvent.EventType.Kick) + { + await Kick(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin); + } + + else if (E.Type == GameEvent.EventType.Warn) + { + await Warn(E.Data, E.Target, E.ImpersonationOrigin ?? E.Origin); + } + + else if (E.Type == GameEvent.EventType.Disconnect) + { ChatHistory.Add(new ChatInfo() { Name = E.Origin.Name, - Message = message, - Time = DateTime.UtcNow, - IsHidden = !string.IsNullOrEmpty(GamePassword) + Message = "DISCONNECTED", + Time = DateTime.UtcNow }); + + await _metaService.AddPersistentMeta("LastMapPlayed", CurrentMap.Alias, E.Origin); + await _metaService.AddPersistentMeta("LastServerPlayed", E.Owner.Hostname, E.Origin); } - } - if (E.Type == GameEvent.EventType.MapChange) - { - Logger.WriteInfo($"New map loaded - {ClientNum} active players"); - - // iw4 doesn't log the game info - if (E.Extra == null) + else if (E.Type == GameEvent.EventType.PreDisconnect) { - var dict = await this.GetInfoAsync(new TimeSpan(0, 0, 20)); + ServerLogger.LogInformation("Detected PreDisconnect for {client} from {source}", + E.Origin.ToString(), E.Source); + bool isPotentialFalseQuit = E.GameTime.HasValue && E.GameTime.Value == lastGameTime; - if (dict == null) + if (isPotentialFalseQuit) { - Logger.WriteWarning("Map change event response doesn't have any data"); + ServerLogger.LogDebug( + "Received PreDisconnect event for {origin}, but it occured at game time {gameTime}, which is the same last map change, so we're ignoring", + E.Origin.ToString(), E.GameTime); + return false; + } + + // predisconnect comes from minimal rcon polled players and minimal log players + // so we need to disconnect the "full" version of the client + var client = GetClientsAsList().FirstOrDefault(_client => _client.Equals(E.Origin)); + + if (client == null) + { + // this can happen when the status picks up the connect before the log does + ServerLogger.LogInformation( + "Ignoring PreDisconnect for {origin} because they are no longer on the client list", + E.Origin.ToString()); + return false; + } + + else if (client.State != ClientState.Unknown) + { + await OnClientDisconnected(client); + return true; } else { - Gametype = dict["gametype"]; - Hostname = dict["hostname"]; - - string mapname = dict["mapname"] ?? CurrentMap.Name; - UpdateMap(mapname); + ServerLogger.LogWarning( + "Expected disconnecting client {client} to be in state {state}, but is in state {clientState}", + client.ToString(), ClientState.Connected.ToString(), client.State); + return false; } } - else + else if (E.Type == GameEvent.EventType.Update) { - var dict = (Dictionary)E.Extra; - Gametype = dict["g_gametype"]; - Hostname = dict["sv_hostname"]; - MaxClients = int.Parse(dict["sv_maxclients"]); - - string mapname = dict["mapname"]; - UpdateMap(mapname); + ServerLogger.LogDebug("Begin Update for {origin}", E.Origin.ToString()); + await OnClientUpdate(E.Origin); } - if (E.GameTime.HasValue) + if (E.Type == GameEvent.EventType.Say) { - lastGameTime = E.GameTime.Value; + if (E.Data?.Length > 0) + { + string message = E.Data; + if (E.Data.IsQuickMessage()) + { + try + { + message = Manager.GetApplicationSettings().Configuration() + .QuickMessages + .First(_qm => _qm.Game == GameName) + .Messages[E.Data.Substring(1)]; + } + catch + { + message = E.Data.Substring(1); + } + } + + ChatHistory.Add(new ChatInfo() + { + Name = E.Origin.Name, + Message = message, + Time = DateTime.UtcNow, + IsHidden = !string.IsNullOrEmpty(GamePassword) + }); + } } - } - if (E.Type == GameEvent.EventType.MapEnd) - { - Logger.WriteInfo("Game ending..."); - - if (E.GameTime.HasValue) + if (E.Type == GameEvent.EventType.MapChange) { - lastGameTime = E.GameTime.Value; + ServerLogger.LogInformation("New map loaded - {clientCount} active players", ClientNum); + + // iw4 doesn't log the game info + if (E.Extra == null) + { + var dict = await this.GetInfoAsync(new TimeSpan(0, 0, 20)); + + if (dict == null) + { + ServerLogger.LogWarning("Map change event response doesn't have any data"); + } + + else + { + Gametype = dict["gametype"]; + Hostname = dict["hostname"]; + + string mapname = dict["mapname"] ?? CurrentMap.Name; + UpdateMap(mapname); + } + } + + else + { + var dict = (Dictionary) E.Extra; + Gametype = dict["g_gametype"]; + Hostname = dict["sv_hostname"]; + MaxClients = int.Parse(dict["sv_maxclients"]); + + string mapname = dict["mapname"]; + UpdateMap(mapname); + } + + if (E.GameTime.HasValue) + { + lastGameTime = E.GameTime.Value; + } } - } - if (E.Type == GameEvent.EventType.Tell) - { - await Tell(E.Message, E.Target); - } - - if (E.Type == GameEvent.EventType.Broadcast) - { - if (!Utilities.IsDevelopment && E.Data != null) // hides broadcast when in development mode + if (E.Type == GameEvent.EventType.MapEnd) { - await E.Owner.ExecuteCommandAsync(E.Data); - } - } + ServerLogger.LogInformation("Game ending..."); - lock (ChatHistory) - { - while (ChatHistory.Count > Math.Ceiling(ClientNum / 2.0)) + if (E.GameTime.HasValue) + { + lastGameTime = E.GameTime.Value; + } + } + + if (E.Type == GameEvent.EventType.Tell) { - ChatHistory.RemoveAt(0); + await Tell(E.Message, E.Target); } - } - // the last client hasn't fully disconnected yet - // so there will still be at least 1 client left - if (ClientNum < 2) - { - ChatHistory.Clear(); - } + if (E.Type == GameEvent.EventType.Broadcast) + { + if (!Utilities.IsDevelopment && E.Data != null) // hides broadcast when in development mode + { + await E.Owner.ExecuteCommandAsync(E.Data); + } + } - return true; + lock (ChatHistory) + { + while (ChatHistory.Count > Math.Ceiling(ClientNum / 2.0)) + { + ChatHistory.RemoveAt(0); + } + } + + // the last client hasn't fully disconnected yet + // so there will still be at least 1 client left + if (ClientNum < 2) + { + ChatHistory.Clear(); + } + + return true; + } } private async Task OnClientUpdate(EFClient origin) @@ -645,7 +658,7 @@ namespace IW4MAdmin if (client == null) { - Logger.WriteWarning($"{origin} expected to exist in client list for update, but they do not"); + ServerLogger.LogWarning("{origin} expected to exist in client list for update, but they do not", origin.ToString()); return; } @@ -664,15 +677,17 @@ namespace IW4MAdmin catch (Exception e) { - Logger.WriteWarning($"Could not execute on join for {origin}"); - Logger.WriteDebug(e.GetExceptionInfo()); + using(LogContext.PushProperty("Server", ToString())) + { + ServerLogger.LogError(e, "Could not execute on join for {origin}", origin.ToString()); + } } } else if ((client.IPAddress != null && client.State == ClientState.Disconnecting) || client.Level == Permission.Banned) { - Logger.WriteWarning($"{client} state is Unknown (probably kicked), but they are still connected. trying to kick again..."); + ServerLogger.LogWarning("{client} state is Unknown (probably kicked), but they are still connected. trying to kick again...", origin.ToString()); await client.CanConnect(client.IPAddress); } } @@ -686,9 +701,6 @@ namespace IW4MAdmin /// async Task[]> PollPlayersAsync() { -#if DEBUG - var now = DateTime.Now; -#endif var currentClients = GetClientsAsList(); var statusResponse = (await this.GetStatusAsync()); var polledClients = statusResponse.Item1.AsEnumerable(); @@ -697,9 +709,6 @@ namespace IW4MAdmin { polledClients = polledClients.Where(c => !c.IsBot); } -#if DEBUG - Logger.WriteInfo($"Polling players took {(DateTime.Now - now).TotalMilliseconds}ms"); -#endif var disconnectingClients = currentClients.Except(polledClients); var connectingClients = polledClients.Except(currentClients); var updatedClients = polledClients.Except(connectingClients).Except(disconnectingClients); @@ -763,9 +772,8 @@ namespace IW4MAdmin DateTime playerCountStart = DateTime.Now; DateTime lastCount = DateTime.Now; - override public async Task ProcessUpdatesAsync(CancellationToken cts) + public override async Task ProcessUpdatesAsync(CancellationToken cts) { - bool notifyDisconnects = !Manager.GetApplicationSettings().Configuration().IgnoreServerConnectionLost; try { if (cts.IsCancellationRequested) @@ -776,12 +784,10 @@ namespace IW4MAdmin try { -#if DEBUG - if (Manager.GetApplicationSettings().Configuration().RConPollRate == int.MaxValue) + if (Manager.GetApplicationSettings().Configuration().RConPollRate == int.MaxValue && Utilities.IsDevelopment) { return true; } -#endif var polledClients = await PollPlayersAsync(); @@ -838,7 +844,7 @@ namespace IW4MAdmin Manager.AddEvent(e); } - if (ConnectionErrors > 0) + if (Throttled) { var _event = new GameEvent() { @@ -851,14 +857,12 @@ namespace IW4MAdmin Manager.AddEvent(_event); } - ConnectionErrors = 0; LastPoll = DateTime.Now; } catch (NetworkException e) { - ConnectionErrors++; - if (ConnectionErrors == 3) + if (!Throttled) { var _event = new GameEvent() { @@ -872,6 +876,7 @@ namespace IW4MAdmin Manager.AddEvent(_event); } + return true; } @@ -916,24 +921,22 @@ namespace IW4MAdmin } // this one is ok - catch (ServerException e) + catch (Exception e) when(e is ServerException || e is RConException) { - if (e is NetworkException && !Throttled && notifyDisconnects) + using(LogContext.PushProperty("Server", ToString())) { - Logger.WriteError(loc["SERVER_ERROR_COMMUNICATION"].FormatExt($"{IP}:{Port}")); - Logger.WriteDebug(e.GetExceptionInfo()); - } - else - { - Logger.WriteError(e.Message); + ServerLogger.LogWarning(e, "Undesirable exception occured during processing updates"); } return false; } - catch (Exception E) + catch (Exception e) { - Logger.WriteError(loc["SERVER_ERROR_EXCEPTION"].FormatExt($"[{IP}:{Port}]")); - Logger.WriteDebug(E.GetExceptionInfo()); + using(LogContext.PushProperty("Server", ToString())) + { + ServerLogger.LogError(e, "Unexpected exception occured during processing updates"); + } + Console.WriteLine(loc["SERVER_ERROR_EXCEPTION"].FormatExt($"[{IP}:{Port}]")); return false; } } @@ -1077,16 +1080,21 @@ namespace IW4MAdmin IsWindows = RuntimeInformation.IsOSPlatform(OSPlatform.Windows) }; LogPath = GenerateLogPath(logInfo); + ServerLogger.LogInformation("Game log information {@logInfo}", logInfo); + if (!File.Exists(LogPath) && ServerConfig.GameLogServerUrl == null) { - Logger.WriteError(loc["SERVER_ERROR_DNE"].FormatExt(LogPath)); + Console.WriteLine(loc["SERVER_ERROR_DNE"].FormatExt(LogPath)); + ServerLogger.LogCritical("Game log path does not exist {logPath}", LogPath); throw new ServerException(loc["SERVER_ERROR_DNE"].FormatExt(LogPath)); } } - LogEvent = new GameLogEventDetection(this, GenerateUriForLog(LogPath, ServerConfig.GameLogServerUrl?.AbsoluteUri), gameLogReaderFactory); - Logger.WriteInfo($"Log file is {LogPath}"); + ServerLogger.LogInformation("Generated game log path is {logPath}", LogPath); + LogEvent = new GameLogEventDetection( _serviceProvider.GetRequiredService>(), + this, + GenerateUriForLog(LogPath, ServerConfig.GameLogServerUrl?.AbsoluteUri), gameLogReaderFactory); _ = Task.Run(() => LogEvent.PollForChanges()); @@ -1165,8 +1173,8 @@ namespace IW4MAdmin Link = targetClient.AliasLink }; - Logger.WriteDebug($"Creating warn penalty for {targetClient}"); - await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), Manager.GetLogger(0)); + ServerLogger.LogDebug("Creating warn penalty for {targetClient}", targetClient.ToString()); + await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), ServerLogger); if (targetClient.IsIngame) { @@ -1176,6 +1184,7 @@ namespace IW4MAdmin return; } + // todo: move to translation sheet string message = $"^1{loc["SERVER_WARNING"]} ^7[^3{targetClient.Warnings}^7]: ^3{targetClient.Name}^7, {reason}"; targetClient.CurrentServer.Broadcast(message); } @@ -1198,8 +1207,8 @@ namespace IW4MAdmin Link = targetClient.AliasLink }; - Logger.WriteDebug($"Creating kick penalty for {targetClient}"); - await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), Manager.GetLogger(0)); + ServerLogger.LogDebug("Creating kick penalty for {targetClient}", targetClient.ToString()); + await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), ServerLogger); if (targetClient.IsIngame) { @@ -1212,6 +1221,7 @@ namespace IW4MAdmin Manager.AddEvent(e); + // todo: move to translation sheet string formattedKick = string.Format(RconParser.Configuration.CommandPrefixes.Kick, targetClient.ClientNumber, $"{loc["SERVER_KICK_TEXT"]} - ^5{Reason}^7"); await targetClient.CurrentServer.ExecuteCommandAsync(formattedKick); } @@ -1235,13 +1245,14 @@ namespace IW4MAdmin Link = targetClient.AliasLink }; - Logger.WriteDebug($"Creating tempban penalty for {targetClient}"); - await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), Manager.GetLogger(0)); + ServerLogger.LogDebug("Creating tempban penalty for {targetClient}", targetClient.ToString()); + await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), ServerLogger); if (targetClient.IsIngame) { + // todo: move to translation sheet string formattedKick = string.Format(RconParser.Configuration.CommandPrefixes.Kick, targetClient.ClientNumber, $"^7{loc["SERVER_TB_TEXT"]}- ^5{Reason}"); - Logger.WriteDebug($"Executing tempban kick command for {targetClient}"); + ServerLogger.LogDebug("Executing tempban kick command for {targetClient}", targetClient.ToString()); await targetClient.CurrentServer.ExecuteCommandAsync(formattedKick); } } @@ -1265,13 +1276,14 @@ namespace IW4MAdmin IsEvadedOffense = isEvade }; - Logger.WriteDebug($"Creating ban penalty for {targetClient}"); + ServerLogger.LogDebug("Creating ban penalty for {targetClient}", targetClient.ToString()); targetClient.SetLevel(Permission.Banned, originClient); - await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), Manager.GetLogger(0)); + await newPenalty.TryCreatePenalty(Manager.GetPenaltyService(), ServerLogger); if (targetClient.IsIngame) { - Logger.WriteDebug($"Attempting to kicking newly banned client {targetClient}"); + ServerLogger.LogDebug("Attempting to kicking newly banned client {targetClient}", targetClient.ToString()); + // todo: move to translation sheet string formattedString = string.Format(RconParser.Configuration.CommandPrefixes.Kick, targetClient.ClientNumber, $"{loc["SERVER_BAN_TEXT"]} - ^5{reason} ^7{loc["SERVER_BAN_APPEAL"].FormatExt(Website)}^7"); await targetClient.CurrentServer.ExecuteCommandAsync(formattedString); } @@ -1291,6 +1303,7 @@ namespace IW4MAdmin Link = Target.AliasLink }; + ServerLogger.LogDebug("Creating unban penalty for {targetClient}", Target.ToString()); Target.SetLevel(Permission.User, Origin); await Manager.GetPenaltyService().RemoveActivePenalties(Target.AliasLink.AliasLinkId); await Manager.GetPenaltyService().Create(unbanPenalty); diff --git a/Application/Localization/Configure.cs b/Application/Localization/Configure.cs index 2a275c724..8d759fd56 100644 --- a/Application/Localization/Configure.cs +++ b/Application/Localization/Configure.cs @@ -6,15 +6,22 @@ using System.Collections.Generic; using System.Globalization; using System.IO; using System.Text; +using Microsoft.Extensions.Logging; +using SharedLibraryCore.Configuration; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Localization { - public class Configure + public static class Configure { - public static ITranslationLookup Initialize(bool useLocalTranslation, IMasterApi apiInstance, string customLocale = null) + public static ITranslationLookup Initialize(ILogger logger, IMasterApi apiInstance, ApplicationConfiguration applicationConfiguration) { - string currentLocale = string.IsNullOrEmpty(customLocale) ? CultureInfo.CurrentCulture.Name : customLocale; - string[] localizationFiles = Directory.GetFiles(Path.Join(Utilities.OperatingDirectory, "Localization"), $"*.{currentLocale}.json"); + var useLocalTranslation = applicationConfiguration?.UseLocalTranslations ?? true; + var customLocale = applicationConfiguration?.EnableCustomLocale ?? false + ? (applicationConfiguration.CustomLocale ?? "en-US") + : "en-US"; + var currentLocale = string.IsNullOrEmpty(customLocale) ? CultureInfo.CurrentCulture.Name : customLocale; + var localizationFiles = Directory.GetFiles(Path.Join(Utilities.OperatingDirectory, "Localization"), $"*.{currentLocale}.json"); if (!useLocalTranslation) { @@ -25,9 +32,10 @@ namespace IW4MAdmin.Application.Localization return localization.LocalizationIndex; } - catch (Exception) + catch (Exception ex) { // the online localization failed so will default to local files + logger.LogWarning(ex, "Could not download latest translations"); } } @@ -60,13 +68,11 @@ namespace IW4MAdmin.Application.Localization { if (!localizationDict.TryAdd(item.Key, item.Value)) { - Program.ServerManager.GetLogger(0).WriteError($"Could not add locale string {item.Key} to localization"); + logger.LogError("Could not add locale string {key} to localization", item.Key); } } } - string localizationFile = $"{Path.Join(Utilities.OperatingDirectory, "Localization")}{Path.DirectorySeparatorChar}IW4MAdmin.{currentLocale}-{currentLocale.ToUpper()}.json"; - Utilities.CurrentLocalization = new SharedLibraryCore.Localization.Layout(localizationDict) { LocalizationName = currentLocale, diff --git a/Application/Main.cs b/Application/Main.cs index 86732d3cd..4d922277b 100644 --- a/Application/Main.cs +++ b/Application/Main.cs @@ -1,7 +1,6 @@ using IW4MAdmin.Application.API.Master; using IW4MAdmin.Application.EventParsers; using IW4MAdmin.Application.Factories; -using IW4MAdmin.Application.Helpers; using IW4MAdmin.Application.Meta; using IW4MAdmin.Application.Migration; using IW4MAdmin.Application.Misc; @@ -24,6 +23,10 @@ using System.Linq; using System.Text; using System.Threading; using System.Threading.Tasks; +using IW4MAdmin.Application.Extensions; +using IW4MAdmin.Application.Localization; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application { @@ -76,29 +79,32 @@ namespace IW4MAdmin.Application { restart: ITranslationLookup translationLookup = null; + var logger = BuildDefaultLogger(new ApplicationConfiguration()); + Utilities.DefaultLogger = logger; + logger.LogInformation("Begin IW4MAdmin startup. Version is {version} {@args}", Version, args); + try { // do any needed housekeeping file/folder migrations ConfigurationMigration.MoveConfigFolder10518(null); ConfigurationMigration.CheckDirectories(); - + logger.LogDebug("Configuring services..."); var services = ConfigureServices(args); serviceProvider = services.BuildServiceProvider(); var versionChecker = serviceProvider.GetRequiredService(); ServerManager = (ApplicationManager)serviceProvider.GetRequiredService(); translationLookup = serviceProvider.GetRequiredService(); - ServerManager.Logger.WriteInfo(Utilities.CurrentLocalization.LocalizationIndex["MANAGER_VERSION"].FormatExt(Version)); - await versionChecker.CheckVersion(); await ServerManager.Init(); } catch (Exception e) { - string failMessage = translationLookup == null ? "Failed to initalize IW4MAdmin" : translationLookup["MANAGER_INIT_FAIL"]; + string failMessage = translationLookup == null ? "Failed to initialize IW4MAdmin" : translationLookup["MANAGER_INIT_FAIL"]; string exitMessage = translationLookup == null ? "Press enter to exit..." : translationLookup["MANAGER_EXIT"]; + logger.LogCritical(e, "Failed to initialize IW4MAdmin"); Console.WriteLine(failMessage); while (e.InnerException != null) @@ -131,13 +137,14 @@ namespace IW4MAdmin.Application try { - ApplicationTask = RunApplicationTasksAsync(); + ApplicationTask = RunApplicationTasksAsync(logger); await ApplicationTask; } catch (Exception e) { - string failMessage = translationLookup == null ? "Failed to initalize IW4MAdmin" : translationLookup["MANAGER_INIT_FAIL"]; + logger.LogCritical(e, "Failed to launch IW4MAdmin"); + string failMessage = translationLookup == null ? "Failed to launch IW4MAdmin" : translationLookup["MANAGER_INIT_FAIL"]; Console.WriteLine($"{failMessage}: {e.GetExceptionInfo()}"); } @@ -153,7 +160,7 @@ namespace IW4MAdmin.Application /// runs the core application tasks /// /// - private static async Task RunApplicationTasksAsync() + private static async Task RunApplicationTasksAsync(ILogger logger) { var webfrontTask = ServerManager.GetApplicationSettings().Configuration().EnableWebFront ? WebfrontCore.Program.Init(ServerManager, serviceProvider, ServerManager.CancellationToken) : @@ -161,7 +168,7 @@ namespace IW4MAdmin.Application // we want to run this one on a manual thread instead of letting the thread pool handle it, // because we can't exit early from waiting on console input, and it prevents us from restarting - var inputThread = new Thread(async () => await ReadConsoleInput()); + var inputThread = new Thread(async () => await ReadConsoleInput(logger)); inputThread.Start(); var tasks = new[] @@ -171,9 +178,11 @@ namespace IW4MAdmin.Application serviceProvider.GetRequiredService().RunUploadStatus(ServerManager.CancellationToken) }; + logger.LogDebug("Starting webfront and input tasks"); await Task.WhenAll(tasks); - ServerManager.Logger.WriteVerbose(Utilities.CurrentLocalization.LocalizationIndex["MANAGER_SHUTDOWN_SUCCESS"]); + logger.LogInformation("Shutdown completed successfully"); + Console.Write(Utilities.CurrentLocalization.LocalizationIndex["MANAGER_SHUTDOWN_SUCCESS"]); } @@ -181,11 +190,11 @@ namespace IW4MAdmin.Application /// reads input from the console and executes entered commands on the default server /// /// - private static async Task ReadConsoleInput() + private static async Task ReadConsoleInput(ILogger logger) { if (Console.IsInputRedirected) { - ServerManager.Logger.WriteInfo("Disabling console input as it has been redirected"); + logger.LogInformation("Disabling console input as it has been redirected"); return; } @@ -221,71 +230,29 @@ namespace IW4MAdmin.Application { } } - /// - /// Configures the dependency injection services - /// - private static IServiceCollection ConfigureServices(string[] args) + private static IServiceCollection HandlePluginRegistration(ApplicationConfiguration appConfig, + IServiceCollection serviceCollection, + IMasterApi masterApi) { - var appConfigHandler = new BaseConfigurationHandler("IW4MAdminSettings"); - var appConfig = appConfigHandler.Configuration(); - var defaultLogger = new Logger("IW4MAdmin-Manager"); - - var masterUri = Utilities.IsDevelopment ? new Uri("http://127.0.0.1:8080") : appConfig?.MasterUrl ?? new ApplicationConfiguration().MasterUrl; - var apiClient = RestClient.For(masterUri); - var pluginImporter = new PluginImporter(defaultLogger, appConfig, apiClient, new RemoteAssemblyHandler(defaultLogger, appConfig)); - - var serviceCollection = new ServiceCollection(); - serviceCollection.AddSingleton(_serviceProvider => serviceCollection) - .AddSingleton(appConfigHandler as IConfigurationHandler) - .AddSingleton(new BaseConfigurationHandler("CommandConfiguration") as IConfigurationHandler) - .AddSingleton(_serviceProvider => _serviceProvider.GetRequiredService>().Configuration() ?? new ApplicationConfiguration()) - .AddSingleton(_serviceProvider => _serviceProvider.GetRequiredService>().Configuration() ?? new CommandConfiguration()) - .AddSingleton(_serviceProvider => defaultLogger) - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton, ClientService>() - .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton, ReceivedPenaltyResourceQueryHelper>() - .AddSingleton, AdministeredPenaltyResourceQueryHelper>() - .AddSingleton, UpdatedAliasResourceQueryHelper>() - .AddSingleton, ChatResourceQueryHelper>() - .AddTransient() + var defaultLogger = BuildDefaultLogger(appConfig); + var pluginServiceProvider = new ServiceCollection() + .AddBaseLogger(appConfig) + .AddSingleton(appConfig) + .AddSingleton(masterApi) .AddSingleton() - .AddSingleton() - .AddSingleton() - .AddSingleton(apiClient) - .AddSingleton(_serviceProvider => - { - var config = _serviceProvider.GetRequiredService>().Configuration(); - return Localization.Configure.Initialize(useLocalTranslation: config?.UseLocalTranslations ?? false, - apiInstance: _serviceProvider.GetRequiredService(), - customLocale: config?.EnableCustomLocale ?? false ? (config.CustomLocale ?? "en-US") : "en-US"); - }); - - if (args.Contains("serialevents")) - { - serviceCollection.AddSingleton(); - } - else - { - serviceCollection.AddSingleton(); - } + .AddSingleton() + .BuildServiceProvider(); + var pluginImporter = pluginServiceProvider.GetRequiredService(); + + // we need to register the rest client with regular collection + serviceCollection.AddSingleton(masterApi); + // register the native commands foreach (var commandType in typeof(SharedLibraryCore.Commands.QuitCommand).Assembly.GetTypes() .Where(_command => _command.BaseType == typeof(Command))) { - defaultLogger.WriteInfo($"Registered native command type {commandType.Name}"); + defaultLogger.LogDebug("Registered native command type {name}", commandType.Name); serviceCollection.AddSingleton(typeof(IManagerCommand), commandType); } @@ -293,14 +260,14 @@ namespace IW4MAdmin.Application var pluginImplementations = pluginImporter.DiscoverAssemblyPluginImplementations(); foreach (var pluginType in pluginImplementations.Item1) { - defaultLogger.WriteInfo($"Registered plugin type {pluginType.FullName}"); + defaultLogger.LogDebug("Registered plugin type {name}", pluginType.FullName); serviceCollection.AddSingleton(typeof(IPlugin), pluginType); } // register the plugin commands foreach (var commandType in pluginImplementations.Item2) { - defaultLogger.WriteInfo($"Registered plugin command type {commandType.FullName}"); + defaultLogger.LogDebug("Registered plugin command type {name}", commandType.FullName); serviceCollection.AddSingleton(typeof(IManagerCommand), commandType); } @@ -324,5 +291,86 @@ namespace IW4MAdmin.Application return serviceCollection; } + + + /// + /// Configures the dependency injection services + /// + private static IServiceCollection ConfigureServices(string[] args) + { + // setup the static resources (config/master api/translations) + var serviceCollection = new ServiceCollection(); + var appConfigHandler = new BaseConfigurationHandler("IW4MAdminSettings"); + var appConfig = appConfigHandler.Configuration(); + var masterUri = Utilities.IsDevelopment + ? new Uri("http://127.0.0.1:8080") + : appConfig?.MasterUrl ?? new ApplicationConfiguration().MasterUrl; + var masterRestClient = RestClient.For(masterUri); + var translationLookup = Configure.Initialize(Utilities.DefaultLogger, masterRestClient, appConfig); + + if (appConfig == null) + { + appConfig = (ApplicationConfiguration) new ApplicationConfiguration().Generate(); + appConfigHandler.Set(appConfig); + appConfigHandler.Save(); + } + + // build the dependency list + HandlePluginRegistration(appConfig, serviceCollection, masterRestClient); + + serviceCollection + .AddBaseLogger(appConfig) + .AddSingleton(_serviceProvider => serviceCollection) + .AddSingleton((IConfigurationHandler) appConfigHandler) + .AddSingleton(new BaseConfigurationHandler("CommandConfiguration") as IConfigurationHandler) + .AddSingleton(appConfig) + .AddSingleton(_serviceProvider => _serviceProvider.GetRequiredService>().Configuration() ?? new CommandConfiguration()) + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton, ClientService>() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton, ReceivedPenaltyResourceQueryHelper>() + .AddSingleton, AdministeredPenaltyResourceQueryHelper>() + .AddSingleton, UpdatedAliasResourceQueryHelper>() + .AddSingleton, ChatResourceQueryHelper>() + .AddTransient() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton() + .AddSingleton(translationLookup); + + if (args.Contains("serialevents")) + { + serviceCollection.AddSingleton(); + } + else + { + serviceCollection.AddSingleton(); + } + + return serviceCollection; + } + + private static ILogger BuildDefaultLogger(ApplicationConfiguration appConfig) + { + var collection = new ServiceCollection() + .AddBaseLogger(appConfig) + .BuildServiceProvider(); + + return collection.GetRequiredService>(); + } } } diff --git a/Application/Meta/AdministeredPenaltyResourceQueryHelper.cs b/Application/Meta/AdministeredPenaltyResourceQueryHelper.cs index 1276a4a6a..76d9fd76a 100644 --- a/Application/Meta/AdministeredPenaltyResourceQueryHelper.cs +++ b/Application/Meta/AdministeredPenaltyResourceQueryHelper.cs @@ -1,11 +1,13 @@ using System.Linq; using System.Threading.Tasks; using Microsoft.EntityFrameworkCore; +using Microsoft.Extensions.Logging; using SharedLibraryCore.Database.Models; using SharedLibraryCore.Dtos.Meta.Responses; using SharedLibraryCore.Helpers; using SharedLibraryCore.Interfaces; using SharedLibraryCore.QueryHelper; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Meta { @@ -18,7 +20,7 @@ namespace IW4MAdmin.Application.Meta private readonly ILogger _logger; private readonly IDatabaseContextFactory _contextFactory; - public AdministeredPenaltyResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory) + public AdministeredPenaltyResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory) { _contextFactory = contextFactory; _logger = logger; diff --git a/Application/Meta/MetaRegistration.cs b/Application/Meta/MetaRegistration.cs index 479f87bb3..7b6516e55 100644 --- a/Application/Meta/MetaRegistration.cs +++ b/Application/Meta/MetaRegistration.cs @@ -6,6 +6,8 @@ using SharedLibraryCore.QueryHelper; using System; using System.Collections.Generic; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Meta { @@ -19,7 +21,7 @@ namespace IW4MAdmin.Application.Meta private readonly IResourceQueryHelper _administeredPenaltyHelper; private readonly IResourceQueryHelper _updatedAliasHelper; - public MetaRegistration(ILogger logger, IMetaService metaService, ITranslationLookup transLookup, IEntityService clientEntityService, + public MetaRegistration(ILogger logger, IMetaService metaService, ITranslationLookup transLookup, IEntityService clientEntityService, IResourceQueryHelper receivedPenaltyHelper, IResourceQueryHelper administeredPenaltyHelper, IResourceQueryHelper updatedAliasHelper) @@ -82,7 +84,7 @@ namespace IW4MAdmin.Application.Meta if (client == null) { - _logger.WriteWarning($"No client found with id {request.ClientId} when generating profile meta"); + _logger.LogWarning("No client found with id {clientId} when generating profile meta", request.ClientId); return metaList; } diff --git a/Application/Meta/ReceivedPenaltyResourceQueryHelper.cs b/Application/Meta/ReceivedPenaltyResourceQueryHelper.cs index 82ed8f9be..de8b38bf2 100644 --- a/Application/Meta/ReceivedPenaltyResourceQueryHelper.cs +++ b/Application/Meta/ReceivedPenaltyResourceQueryHelper.cs @@ -2,12 +2,14 @@ using System.Linq; using System.Threading.Tasks; using Microsoft.EntityFrameworkCore; +using Microsoft.Extensions.Logging; using SharedLibraryCore; using SharedLibraryCore.Database.Models; using SharedLibraryCore.Dtos.Meta.Responses; using SharedLibraryCore.Helpers; using SharedLibraryCore.Interfaces; using SharedLibraryCore.QueryHelper; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Meta { @@ -20,7 +22,7 @@ namespace IW4MAdmin.Application.Meta private readonly ILogger _logger; private readonly IDatabaseContextFactory _contextFactory; - public ReceivedPenaltyResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory) + public ReceivedPenaltyResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory) { _contextFactory = contextFactory; _logger = logger; diff --git a/Application/Meta/UpdatedAliasResourceQueryHelper.cs b/Application/Meta/UpdatedAliasResourceQueryHelper.cs index d5ad99896..0adca9f1c 100644 --- a/Application/Meta/UpdatedAliasResourceQueryHelper.cs +++ b/Application/Meta/UpdatedAliasResourceQueryHelper.cs @@ -6,6 +6,8 @@ using SharedLibraryCore.Interfaces; using SharedLibraryCore.QueryHelper; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Meta { @@ -18,7 +20,7 @@ namespace IW4MAdmin.Application.Meta private readonly ILogger _logger; private readonly IDatabaseContextFactory _contextFactory; - public UpdatedAliasResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory) + public UpdatedAliasResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory) { _logger = logger; _contextFactory = contextFactory; diff --git a/Application/Migration/ConfigurationMigration.cs b/Application/Migration/ConfigurationMigration.cs index d7a421b4f..814344b0a 100644 --- a/Application/Migration/ConfigurationMigration.cs +++ b/Application/Migration/ConfigurationMigration.cs @@ -1,11 +1,8 @@ using SharedLibraryCore; -using SharedLibraryCore.Interfaces; using System; -using System.Collections.Generic; using System.IO; using System.Linq; -using System.Text; -using System.Text.RegularExpressions; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Migration { @@ -56,7 +53,6 @@ namespace IW4MAdmin.Application.Migration if (!Directory.Exists(configDirectory)) { - log?.WriteDebug($"Creating directory for configs {configDirectory}"); Directory.CreateDirectory(configDirectory); } @@ -66,7 +62,6 @@ namespace IW4MAdmin.Application.Migration foreach (var configFile in configurationFiles) { - log?.WriteDebug($"Moving config file {configFile}"); string destinationPath = Path.Join("Configuration", configFile); if (!File.Exists(destinationPath)) { @@ -77,7 +72,6 @@ namespace IW4MAdmin.Application.Migration if (!File.Exists(Path.Join("Database", "Database.db")) && File.Exists("Database.db")) { - log?.WriteDebug("Moving database file"); File.Move("Database.db", Path.Join("Database", "Database.db")); } } diff --git a/Application/Misc/EventProfiler.cs b/Application/Misc/EventProfiler.cs deleted file mode 100644 index 0b884f670..000000000 --- a/Application/Misc/EventProfiler.cs +++ /dev/null @@ -1,63 +0,0 @@ -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 : IComparer 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 Events { get; private set; } = new SortedList(new DuplicateKeyComparer()); - 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}"); - } - } -} diff --git a/Application/Misc/Logger.cs b/Application/Misc/Logger.cs index 96cbda547..8647118fe 100644 --- a/Application/Misc/Logger.cs +++ b/Application/Misc/Logger.cs @@ -1,132 +1,47 @@ -using IW4MAdmin.Application.IO; -using SharedLibraryCore; -using SharedLibraryCore.Interfaces; -using System; -using System.Diagnostics; -using System.IO; -using System.Threading; +using System; +using Microsoft.Extensions.Logging; +using ILogger = SharedLibraryCore.Interfaces.ILogger; namespace IW4MAdmin.Application { + [Obsolete] public class Logger : ILogger { - enum LogType + private readonly Microsoft.Extensions.Logging.ILogger _logger; + + public Logger(ILogger logger) { - Verbose, - Info, - Debug, - Warning, - Error, - Assert - } - - readonly string FileName; - readonly ReaderWriterLockSlim WritingLock; - static readonly short MAX_LOG_FILES = 10; - - public Logger(string fn) - { - FileName = Path.Join(Utilities.OperatingDirectory, "Log", $"{fn}.log"); - WritingLock = new ReaderWriterLockSlim(); - RotateLogs(); - } - - ~Logger() - { - WritingLock.Dispose(); - } - - /// - /// rotates logs when log is initialized - /// - private void RotateLogs() - { - string maxLog = FileName + MAX_LOG_FILES; - - if (File.Exists(maxLog)) - { - File.Delete(maxLog); - } - - for (int i = MAX_LOG_FILES - 1; i >= 0; i--) - { - string logToMove = i == 0 ? FileName : FileName + i; - string movedLogName = FileName + (i + 1); - - if (File.Exists(logToMove)) - { - File.Move(logToMove, movedLogName); - } - } - } - - void Write(string msg, LogType type) - { - WritingLock.EnterWriteLock(); - - string stringType = type.ToString(); - msg = msg.StripColors(); - - try - { - stringType = Utilities.CurrentLocalization.LocalizationIndex[$"GLOBAL_{type.ToString().ToUpper()}"]; - } - - catch (Exception) { } - - string LogLine = $"[{DateTime.Now.ToString("MM.dd.yyy HH:mm:ss.fff")}] - {stringType}: {msg}"; - try - { -#if DEBUG - // lets keep it simple and dispose of everything quickly as logging wont be that much (relatively) - Console.WriteLine(msg); -#else - if (type == LogType.Error || type == LogType.Verbose) - { - Console.WriteLine(LogLine); - } - File.AppendAllText(FileName, $"{LogLine}{Environment.NewLine}"); -#endif - } - - catch (Exception ex) - { - Console.WriteLine("Well.. It looks like your machine can't event write to the log file. That's something else..."); - Console.WriteLine(ex.GetExceptionInfo()); - } - - WritingLock.ExitWriteLock(); + _logger = logger; } public void WriteVerbose(string msg) { - Write(msg, LogType.Verbose); + _logger.LogInformation(msg); } public void WriteDebug(string msg) { - Write(msg, LogType.Debug); + _logger.LogDebug(msg); } public void WriteError(string msg) { - Write(msg, LogType.Error); + _logger.LogError(msg); } public void WriteInfo(string msg) { - Write(msg, LogType.Info); + WriteVerbose(msg); } public void WriteWarning(string msg) { - Write(msg, LogType.Warning); + _logger.LogWarning(msg); } public void WriteAssert(bool condition, string msg) { - if (!condition) - Write(msg, LogType.Assert); + throw new NotImplementedException(); } } } diff --git a/Application/Misc/MasterCommunication.cs b/Application/Misc/MasterCommunication.cs index 60dc6891d..e94b80896 100644 --- a/Application/Misc/MasterCommunication.cs +++ b/Application/Misc/MasterCommunication.cs @@ -8,6 +8,8 @@ using System; using System.Linq; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Misc { @@ -24,10 +26,9 @@ namespace IW4MAdmin.Application.Misc private readonly ApplicationConfiguration _appConfig; private readonly BuildNumber _fallbackVersion = BuildNumber.Parse("99.99.99.99"); private readonly int _apiVersion = 1; - private bool firstHeartBeat = true; - public MasterCommunication(ILogger logger, ApplicationConfiguration appConfig, ITranslationLookup translationLookup, IMasterApi apiInstance, IManager manager) + public MasterCommunication(ILogger logger, ApplicationConfiguration appConfig, ITranslationLookup translationLookup, IMasterApi apiInstance, IManager manager) { _logger = logger; _transLookup = translationLookup; @@ -55,13 +56,7 @@ namespace IW4MAdmin.Application.Misc catch (Exception e) { - _logger.WriteWarning(_transLookup["MANAGER_VERSION_FAIL"]); - while (e.InnerException != null) - { - e = e.InnerException; - } - - _logger.WriteDebug(e.Message); + _logger.LogWarning(e, "Unable to retrieve IW4MAdmin version information"); } if (version.CurrentVersionStable == _fallbackVersion) @@ -110,12 +105,12 @@ namespace IW4MAdmin.Application.Misc catch (System.Net.Http.HttpRequestException e) { - _logger.WriteWarning($"Could not send heartbeat - {e.Message}"); + _logger.LogWarning(e, "Could not send heartbeat"); } catch (AggregateException e) { - _logger.WriteWarning($"Could not send heartbeat - {e.Message}"); + _logger.LogWarning(e, "Could not send heartbeat"); var exceptions = e.InnerExceptions.Where(ex => ex.GetType() == typeof(ApiException)); foreach (var ex in exceptions) @@ -129,7 +124,7 @@ namespace IW4MAdmin.Application.Misc catch (ApiException e) { - _logger.WriteWarning($"Could not send heartbeat - {e.Message}"); + _logger.LogWarning(e, "Could not send heartbeat"); if (e.StatusCode == System.Net.HttpStatusCode.Unauthorized) { connected = false; @@ -138,7 +133,7 @@ namespace IW4MAdmin.Application.Misc catch (Exception e) { - _logger.WriteWarning($"Could not send heartbeat - {e.Message}"); + _logger.LogWarning(e, "Could not send heartbeat"); } @@ -202,7 +197,7 @@ namespace IW4MAdmin.Application.Misc if (response.ResponseMessage.StatusCode != System.Net.HttpStatusCode.OK) { - _logger.WriteWarning($"Response code from master is {response.ResponseMessage.StatusCode}, message is {response.StringContent}"); + _logger.LogWarning("Non success response code from master is {statusCode}, message is {message}", response.ResponseMessage.StatusCode, response.StringContent); } } } diff --git a/Application/Misc/MetaService.cs b/Application/Misc/MetaService.cs index 0f98ad7c2..31a621529 100644 --- a/Application/Misc/MetaService.cs +++ b/Application/Misc/MetaService.cs @@ -7,6 +7,8 @@ using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Misc { @@ -20,7 +22,7 @@ namespace IW4MAdmin.Application.Misc private readonly IDatabaseContextFactory _contextFactory; private readonly ILogger _logger; - public MetaService(ILogger logger, IDatabaseContextFactory contextFactory) + public MetaService(ILogger logger, IDatabaseContextFactory contextFactory) { _logger = logger; _metaActions = new Dictionary>(); diff --git a/Application/Misc/MiddlewareActionHandler.cs b/Application/Misc/MiddlewareActionHandler.cs index b038f23ad..a36836236 100644 --- a/Application/Misc/MiddlewareActionHandler.cs +++ b/Application/Misc/MiddlewareActionHandler.cs @@ -1,8 +1,9 @@ -using SharedLibraryCore; -using SharedLibraryCore.Interfaces; +using SharedLibraryCore.Interfaces; using System; using System.Collections.Generic; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Misc { @@ -11,7 +12,7 @@ namespace IW4MAdmin.Application.Misc private readonly IDictionary> _actions; private readonly ILogger _logger; - public MiddlewareActionHandler(ILogger logger) + public MiddlewareActionHandler(ILogger logger) { _actions = new Dictionary>(); _logger = logger; @@ -38,8 +39,7 @@ namespace IW4MAdmin.Application.Misc } catch (Exception e) { - _logger.WriteWarning($"Failed to invoke middleware action {name}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Failed to invoke middleware action {name}", name); } } diff --git a/Application/Misc/PluginImporter.cs b/Application/Misc/PluginImporter.cs index 29723eba4..79318b402 100644 --- a/Application/Misc/PluginImporter.cs +++ b/Application/Misc/PluginImporter.cs @@ -5,11 +5,12 @@ using System.Reflection; using SharedLibraryCore.Interfaces; using System.Linq; using SharedLibraryCore; -using IW4MAdmin.Application.Misc; using IW4MAdmin.Application.API.Master; +using Microsoft.Extensions.Logging; using SharedLibraryCore.Configuration; +using ILogger = Microsoft.Extensions.Logging.ILogger; -namespace IW4MAdmin.Application.Helpers +namespace IW4MAdmin.Application.Misc { /// /// implementation of IPluginImporter @@ -24,7 +25,7 @@ namespace IW4MAdmin.Application.Helpers private readonly IMasterApi _masterApi; private readonly ApplicationConfiguration _appConfig; - public PluginImporter(ILogger logger, ApplicationConfiguration appConfig, IMasterApi masterApi, IRemoteAssemblyHandler remoteAssemblyHandler) + public PluginImporter(ILogger logger, ApplicationConfiguration appConfig, IMasterApi masterApi, IRemoteAssemblyHandler remoteAssemblyHandler) { _logger = logger; _masterApi = masterApi; @@ -44,14 +45,14 @@ namespace IW4MAdmin.Application.Helpers { var scriptPluginFiles = Directory.GetFiles(pluginDir, "*.js").AsEnumerable().Union(GetRemoteScripts()); - _logger.WriteInfo($"Discovered {scriptPluginFiles.Count()} potential script plugins"); + _logger.LogDebug("Discovered {count} potential script plugins", scriptPluginFiles.Count()); if (scriptPluginFiles.Count() > 0) { foreach (string fileName in scriptPluginFiles) { - _logger.WriteInfo($"Discovered script plugin {fileName}"); - var plugin = new ScriptPlugin(fileName); + _logger.LogDebug("Discovered script plugin {fileName}", fileName); + var plugin = new ScriptPlugin(_logger, fileName); yield return plugin; } } @@ -71,7 +72,7 @@ namespace IW4MAdmin.Application.Helpers if (Directory.Exists(pluginDir)) { var dllFileNames = Directory.GetFiles(pluginDir, "*.dll"); - _logger.WriteInfo($"Discovered {dllFileNames.Length} potential plugin assemblies"); + _logger.LogDebug("Discovered {count} potential plugin assemblies", dllFileNames.Length); if (dllFileNames.Length > 0) { @@ -84,13 +85,13 @@ namespace IW4MAdmin.Application.Helpers .SelectMany(_asm => _asm.GetTypes()) .Where(_assemblyType => _assemblyType.GetInterface(nameof(IPlugin), false) != null); - _logger.WriteInfo($"Discovered {pluginTypes.Count()} plugin implementations"); + _logger.LogDebug("Discovered {count} plugin implementations", pluginTypes.Count()); commandTypes = assemblies .SelectMany(_asm => _asm.GetTypes()) .Where(_assemblyType => _assemblyType.IsClass && _assemblyType.BaseType == typeof(Command)); - _logger.WriteInfo($"Discovered {commandTypes.Count()} plugin commands"); + _logger.LogDebug("Discovered {count} plugin commands", commandTypes.Count()); } } @@ -109,8 +110,7 @@ namespace IW4MAdmin.Application.Helpers catch (Exception ex) { - _logger.WriteWarning("Could not load remote assemblies"); - _logger.WriteDebug(ex.GetExceptionInfo()); + _logger.LogWarning(ex, "Could not load remote assemblies"); return Enumerable.Empty(); } } @@ -127,8 +127,7 @@ namespace IW4MAdmin.Application.Helpers catch (Exception ex) { - _logger.WriteWarning("Could not load remote assemblies"); - _logger.WriteDebug(ex.GetExceptionInfo()); + _logger.LogWarning(ex,"Could not load remote scripts"); return Enumerable.Empty(); } } diff --git a/Application/Misc/RemoteAssemblyHandler.cs b/Application/Misc/RemoteAssemblyHandler.cs index 1733495c1..f2214d99c 100644 --- a/Application/Misc/RemoteAssemblyHandler.cs +++ b/Application/Misc/RemoteAssemblyHandler.cs @@ -1,5 +1,4 @@ -using SharedLibraryCore; -using SharedLibraryCore.Configuration; +using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; using System; using System.Collections.Generic; @@ -7,6 +6,8 @@ using System.Linq; using System.Reflection; using System.Security.Cryptography; using System.Text; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Misc { @@ -20,7 +21,7 @@ namespace IW4MAdmin.Application.Misc private readonly ApplicationConfiguration _appconfig; private readonly ILogger _logger; - public RemoteAssemblyHandler(ILogger logger, ApplicationConfiguration appconfig) + public RemoteAssemblyHandler(ILogger logger, ApplicationConfiguration appconfig) { _appconfig = appconfig; _logger = logger; @@ -41,7 +42,7 @@ namespace IW4MAdmin.Application.Misc { if (string.IsNullOrEmpty(_appconfig.Id) || string.IsNullOrWhiteSpace(_appconfig.SubscriptionId)) { - _logger.WriteWarning($"{nameof(_appconfig.Id)} and {nameof(_appconfig.SubscriptionId)} must be provided to attempt loading remote assemblies/scripts"); + _logger.LogWarning($"{nameof(_appconfig.Id)} and {nameof(_appconfig.SubscriptionId)} must be provided to attempt loading remote assemblies/scripts"); return new byte[0][]; } @@ -63,8 +64,7 @@ namespace IW4MAdmin.Application.Misc catch (CryptographicException ex) { - _logger.WriteError("Could not obtain remote plugin assemblies"); - _logger.WriteDebug(ex.GetExceptionInfo()); + _logger.LogError(ex, "Could not decrypt remote plugin assemblies"); } return decryptedContent; diff --git a/Application/Misc/ScriptCommand.cs b/Application/Misc/ScriptCommand.cs index 6f181bba9..b4fe43a12 100644 --- a/Application/Misc/ScriptCommand.cs +++ b/Application/Misc/ScriptCommand.cs @@ -4,7 +4,9 @@ using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; using System; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.Database.Models.EFClient; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Misc { @@ -14,13 +16,15 @@ namespace IW4MAdmin.Application.Misc public class ScriptCommand : Command { private readonly Action _executeAction; + private readonly ILogger _logger; public ScriptCommand(string name, string alias, string description, bool isTargetRequired, Permission permission, - CommandArgument[] args, Action executeAction, CommandConfiguration config, ITranslationLookup layout) + CommandArgument[] args, Action executeAction, CommandConfiguration config, ITranslationLookup layout, ILogger logger) : base(config, layout) { _executeAction = executeAction; + _logger = logger; Name = name; Alias = alias; Description = description; @@ -29,14 +33,21 @@ namespace IW4MAdmin.Application.Misc Arguments = args; } - public override Task ExecuteAsync(GameEvent E) + public override async Task ExecuteAsync(GameEvent e) { if (_executeAction == null) { throw new InvalidOperationException($"No execute action defined for command \"{Name}\""); } - return Task.Run(() => _executeAction(E)); + try + { + await Task.Run(() => _executeAction(e)); + } + catch (Exception ex) + { + _logger.LogError(ex, "Failed to execute ScriptCommand action for command {command} {@event}", Name, e); + } } } } diff --git a/Application/Misc/ScriptPlugin.cs b/Application/Misc/ScriptPlugin.cs index c8dd97da0..4075cac34 100644 --- a/Application/Misc/ScriptPlugin.cs +++ b/Application/Misc/ScriptPlugin.cs @@ -1,4 +1,5 @@ -using Jint; +using System; +using Jint; using Jint.Native; using Jint.Runtime; using Microsoft.CSharp.RuntimeBinder; @@ -12,6 +13,9 @@ using System.Linq; using System.Text; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.Misc { @@ -39,9 +43,11 @@ namespace IW4MAdmin.Application.Misc private readonly SemaphoreSlim _onProcessing; private bool successfullyLoaded; private readonly List _registeredCommandNames; + private readonly ILogger _logger; - public ScriptPlugin(string filename, string workingDirectory = null) + public ScriptPlugin(ILogger logger, string filename, string workingDirectory = null) { + _logger = logger; _fileName = filename; Watcher = new FileSystemWatcher() { @@ -84,7 +90,7 @@ namespace IW4MAdmin.Application.Misc foreach (string commandName in _registeredCommandNames) { - manager.GetLogger(0).WriteDebug($"Removing plugin registered command \"{commandName}\""); + _logger.LogDebug("Removing plugin registered command {command}", commandName); manager.RemoveCommandByName(commandName); } @@ -129,7 +135,7 @@ namespace IW4MAdmin.Application.Misc { foreach (var command in GenerateScriptCommands(commands, scriptCommandFactory)) { - manager.GetLogger(0).WriteDebug($"Adding plugin registered command \"{command.Name}\""); + _logger.LogDebug("Adding plugin registered command {commandName}", command.Name); manager.AddAdditionalCommand(command); _registeredCommandNames.Add(command.Name); } @@ -167,12 +173,20 @@ namespace IW4MAdmin.Application.Misc catch (JavaScriptException ex) { - throw new PluginException($"An error occured while initializing script plugin: {ex.Error} (Line: {ex.Location.Start.Line}, Character: {ex.Location.Start.Column})") { PluginFile = _fileName }; + _logger.LogError(ex, + "Encountered JavaScript runtime error while executing {methodName} for script plugin {plugin} initialization {@locationInfo}", + nameof(OnLoadAsync), _fileName, ex.Location); + + throw new PluginException("An error occured while initializing script plugin"); } - - catch + + catch (Exception ex) { - throw; + _logger.LogError(ex, + "Encountered unexpected error while running {methodName} for script plugin {plugin} with event type {eventType}", + nameof(OnLoadAsync), _fileName); + + throw new PluginException("An unexpected error occured while initializing script plugin"); } finally @@ -197,10 +211,29 @@ namespace IW4MAdmin.Application.Misc _scriptEngine.SetValue("_IW4MAdminClient", Utilities.IW4MAdminClient(S)); _scriptEngine.Execute("plugin.onEventAsync(_gameEvent, _server)").GetCompletionValue(); } - - catch + + catch (JavaScriptException ex) { - throw; + using (LogContext.PushProperty("Server", S.ToString())) + { + _logger.LogError(ex, + "Encountered JavaScript runtime error while executing {methodName} for script plugin {plugin} with event type {eventType} {@locationInfo}", + nameof(OnEventAsync), _fileName, E.Type, ex.Location); + } + + throw new PluginException($"An error occured while executing action for script plugin"); + } + + catch (Exception e) + { + using (LogContext.PushProperty("Server", S.ToString())) + { + _logger.LogError(e, + "Encountered unexpected error while running {methodName} for script plugin {plugin} with event type {eventType}", + nameof(OnEventAsync), _fileName, E.Type); + } + + throw new PluginException($"An error occured while executing action for script plugin"); } finally @@ -215,7 +248,7 @@ namespace IW4MAdmin.Application.Misc public Task OnLoadAsync(IManager manager) { - manager.GetLogger(0).WriteDebug($"OnLoad executing for {Name}"); + _logger.LogDebug("OnLoad executing for {name}", Name); _scriptEngine.SetValue("_manager", manager); return Task.FromResult(_scriptEngine.Execute("plugin.onLoadAsync(_manager)").GetCompletionValue()); } diff --git a/Application/RCon/RConConnection.cs b/Application/RCon/RConConnection.cs index 8dbadbb39..c320800cf 100644 --- a/Application/RCon/RConConnection.cs +++ b/Application/RCon/RConConnection.cs @@ -11,6 +11,9 @@ using System.Net.Sockets; using System.Text; using System.Text.RegularExpressions; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.RCon { @@ -27,7 +30,7 @@ namespace IW4MAdmin.Application.RCon private readonly ILogger _log; private readonly Encoding _gameEncoding; - public RConConnection(string ipAddress, int port, string password, ILogger log, Encoding gameEncoding) + public RConConnection(string ipAddress, int port, string password, ILogger log, Encoding gameEncoding) { Endpoint = new IPEndPoint(IPAddress.Parse(ipAddress), port); _gameEncoding = gameEncoding; @@ -49,10 +52,7 @@ namespace IW4MAdmin.Application.RCon var connectionState = ActiveQueries[this.Endpoint]; - if (Utilities.IsDevelopment) - { - _log.WriteDebug($"Waiting for semaphore to be released [{this.Endpoint}]"); - } + _log.LogDebug("Waiting for semaphore to be released [{endpoint}]", Endpoint); // enter the semaphore so only one query is sent at a time per server. await connectionState.OnComplete.WaitAsync(); @@ -66,11 +66,8 @@ namespace IW4MAdmin.Application.RCon connectionState.LastQuery = DateTime.Now; - if (Utilities.IsDevelopment) - { - _log.WriteDebug($"Semaphore has been released [{Endpoint}]"); - _log.WriteDebug($"Query [{Endpoint},{type},{parameters}]"); - } + _log.LogDebug("Semaphore has been released [{endpoint}]", Endpoint); + _log.LogDebug("Query {@queryInfo}", new { endpoint=Endpoint.ToString(), type, parameters }); byte[] payload = null; bool waitForResponse = config.WaitForResponse; @@ -115,10 +112,16 @@ namespace IW4MAdmin.Application.RCon // this happens when someone tries to send something that can't be converted into a 7 bit character set // e.g: emoji -> windows-1252 - catch (OverflowException) + catch (OverflowException ex) { connectionState.OnComplete.Release(1); - throw new NetworkException($"Invalid character encountered when converting encodings - {parameters}"); + using (LogContext.PushProperty("Server", Endpoint.ToString())) + { + _log.LogError(ex, "Could not convert RCon data payload to desired encoding {encoding} {params}", + _gameEncoding.EncodingName, parameters); + } + + throw new RConException($"Invalid character encountered when converting encodings"); } byte[][] response = null; @@ -137,16 +140,17 @@ namespace IW4MAdmin.Application.RCon connectionState.ConnectionAttempts++; connectionState.BytesReadPerSegment.Clear(); bool exceptionCaught = false; -#if DEBUG == true - _log.WriteDebug($"Sending {payload.Length} bytes to [{this.Endpoint}] ({connectionState.ConnectionAttempts}/{StaticHelpers.AllowedConnectionFails})"); -#endif + + _log.LogDebug("Sending {payloadLength} bytes to [{endpoint}] ({connectionAttempts}/{allowedConnectionFailures})", + payload.Length, Endpoint, connectionState.ConnectionAttempts, StaticHelpers.AllowedConnectionFails); + try { response = await SendPayloadAsync(payload, waitForResponse); if ((response.Length == 0 || response[0].Length == 0) && waitForResponse) { - throw new NetworkException("Expected response but got 0 bytes back"); + throw new RConException("Expected response but got 0 bytes back"); } connectionState.ConnectionAttempts = 0; @@ -162,7 +166,14 @@ namespace IW4MAdmin.Application.RCon goto retrySend; } - throw new NetworkException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_COMMUNICATION"].FormatExt(Endpoint)); + using (LogContext.PushProperty("Server", Endpoint.ToString())) + { + _log.LogWarning( + "Made {connectionAttempts} attempts to send RCon data to server, but received no response", + connectionState.ConnectionAttempts); + } + connectionState.ConnectionAttempts = 0; + throw new NetworkException("Reached maximum retry attempts to send RCon data to server"); } finally @@ -177,7 +188,7 @@ namespace IW4MAdmin.Application.RCon if (response.Length == 0) { - _log.WriteWarning($"Received empty response for request [{type}, {parameters}, {Endpoint}]"); + _log.LogDebug("Received empty response for RCon request {@query}", new { endpoint=Endpoint.ToString(), type, parameters }); return new string[0]; } @@ -187,12 +198,12 @@ namespace IW4MAdmin.Application.RCon // note: not all games respond if the pasword is wrong or not set if (responseString.Contains("Invalid password") || responseString.Contains("rconpassword")) { - throw new NetworkException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_RCON_INVALID"]); + throw new RConException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_RCON_INVALID"]); } if (responseString.Contains("rcon_password")) { - throw new NetworkException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_RCON_NOTSET"]); + throw new RConException(Utilities.CurrentLocalization.LocalizationIndex["SERVER_ERROR_RCON_NOTSET"]); } if (responseString.Contains(config.ServerNotRunningResponse)) @@ -205,7 +216,13 @@ namespace IW4MAdmin.Application.RCon if (headerSplit.Length != 2) { - throw new NetworkException("Unexpected response header from server"); + using (LogContext.PushProperty("Server", Endpoint.ToString())) + { + _log.LogWarning("Invalid response header from server. Expected {expected}, but got {response}", + config.CommandPrefixes.RConResponse, headerSplit.FirstOrDefault()); + } + + throw new RConException("Unexpected response header from server"); } string[] splitResponse = headerSplit.Last().Split(new char[] { '\n' }, StringSplitOptions.RemoveEmptyEntries); @@ -293,12 +310,17 @@ namespace IW4MAdmin.Application.RCon if (sendDataPending) { - // the send has not been completed asyncronously + // the send has not been completed asynchronously // this really shouldn't ever happen because it's UDP if (!await Task.Run(() => connectionState.OnSentData.Wait(StaticHelpers.SocketTimeout(1)))) { + using(LogContext.PushProperty("Server", Endpoint.ToString())) + { + _log.LogWarning("Socket timed out while sending RCon data on attempt {attempt}", + connectionState.ConnectionAttempts); + } rconSocket.Close(); - throw new NetworkException("Timed out sending data", rconSocket); + throw new NetworkException("Timed out sending RCon data", rconSocket); } } @@ -314,14 +336,22 @@ namespace IW4MAdmin.Application.RCon if (receiveDataPending) { - if (Utilities.IsDevelopment) - { - _log.WriteDebug($"Waiting to asynchrously receive data on attempt #{connectionState.ConnectionAttempts}"); - } + _log.LogDebug("Waiting to asynchronously receive data on attempt #{connectionAttempts}", connectionState.ConnectionAttempts); if (!await Task.Run(() => connectionState.OnReceivedData.Wait(StaticHelpers.SocketTimeout(connectionState.ConnectionAttempts)))) { + if (connectionState.ConnectionAttempts > 1) // this reduces some spam for unstable connections + { + using (LogContext.PushProperty("Server", Endpoint.ToString())) + { + _log.LogWarning( + "Socket timed out while waiting for RCon response on attempt {attempt} with timeout delay of {timeout}", + connectionState.ConnectionAttempts, + StaticHelpers.SocketTimeout(connectionState.ConnectionAttempts)); + } + } + rconSocket.Close(); - throw new NetworkException("Timed out waiting for response", rconSocket); + throw new NetworkException("Timed out receiving RCon response", rconSocket); } } @@ -350,10 +380,7 @@ namespace IW4MAdmin.Application.RCon private void OnDataReceived(object sender, SocketAsyncEventArgs e) { - if (Utilities.IsDevelopment) - { - _log.WriteDebug($"Read {e.BytesTransferred} bytes from {e.RemoteEndPoint}"); - } + _log.LogDebug("Read {bytesTransferred} bytes from {endpoint}", e.BytesTransferred, e.RemoteEndPoint); // this occurs when we close the socket if (e.BytesTransferred == 0) @@ -376,10 +403,7 @@ namespace IW4MAdmin.Application.RCon if (!sock.ReceiveAsync(state.ReceiveEventArgs)) { - if (Utilities.IsDevelopment) - { - _log.WriteDebug($"Read {state.ReceiveEventArgs.BytesTransferred} synchronous bytes from {e.RemoteEndPoint}"); - } + _log.LogDebug("Read {bytesTransferred} synchronous bytes from {endpoint}", state.ReceiveEventArgs.BytesTransferred, e.RemoteEndPoint); // we need to increment this here because the callback isn't executed if there's no pending IO state.BytesReadPerSegment.Add(state.ReceiveEventArgs.BytesTransferred); ActiveQueries[this.Endpoint].OnReceivedData.Set(); @@ -401,10 +425,7 @@ namespace IW4MAdmin.Application.RCon private void OnDataSent(object sender, SocketAsyncEventArgs e) { - if (Utilities.IsDevelopment) - { - _log.WriteDebug($"Sent {e.Buffer?.Length} bytes to {e.ConnectSocket?.RemoteEndPoint?.ToString()}"); - } + _log.LogDebug("Sent {byteCount} bytes to {endpoint}", e.Buffer?.Length, e.ConnectSocket?.RemoteEndPoint); ActiveQueries[this.Endpoint].OnSentData.Set(); } } diff --git a/Application/RconParsers/BaseRConParser.cs b/Application/RconParsers/BaseRConParser.cs index d797111c1..6b8b63a8b 100644 --- a/Application/RconParsers/BaseRConParser.cs +++ b/Application/RconParsers/BaseRConParser.cs @@ -8,14 +8,19 @@ using System.Collections.Generic; using System.Linq; using System.Text.RegularExpressions; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.Server; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Application.RconParsers { public class BaseRConParser : IRConParser { - public BaseRConParser(IParserRegexFactory parserRegexFactory) + private readonly ILogger _logger; + + public BaseRConParser(ILogger logger, IParserRegexFactory parserRegexFactory) { + _logger = logger; Configuration = new DynamicRConParserConfiguration(parserRegexFactory) { CommandPrefixes = new CommandPrefix() @@ -133,12 +138,7 @@ namespace IW4MAdmin.Application.RconParsers public virtual async Task<(List, string, string)> GetStatusAsync(IRConConnection connection) { string[] response = await connection.SendQueryAsync(StaticHelpers.QueryType.COMMAND_STATUS); -#if DEBUG - foreach (var line in response) - { - Console.WriteLine(line); - } -#endif + _logger.LogDebug("Status Response {@response}", (object)response); return (ClientsFromStatus(response), MapFromStatus(response), GameTypeFromStatus(response)); } diff --git a/Application/RconParsers/DynamicRConParser.cs b/Application/RconParsers/DynamicRConParser.cs index 380062f13..f642a5b95 100644 --- a/Application/RconParsers/DynamicRConParser.cs +++ b/Application/RconParsers/DynamicRConParser.cs @@ -1,4 +1,5 @@ -using SharedLibraryCore.Interfaces; +using Microsoft.Extensions.Logging; +using SharedLibraryCore.Interfaces; namespace IW4MAdmin.Application.RconParsers { @@ -8,7 +9,7 @@ namespace IW4MAdmin.Application.RconParsers /// sealed internal class DynamicRConParser : BaseRConParser { - public DynamicRConParser(IParserRegexFactory parserRegexFactory) : base(parserRegexFactory) + public DynamicRConParser(ILogger logger, IParserRegexFactory parserRegexFactory) : base(logger, parserRegexFactory) { } } diff --git a/Plugins/AutomessageFeed/AutomessageFeed.csproj b/Plugins/AutomessageFeed/AutomessageFeed.csproj index 2a894b5ca..fc817db32 100644 --- a/Plugins/AutomessageFeed/AutomessageFeed.csproj +++ b/Plugins/AutomessageFeed/AutomessageFeed.csproj @@ -10,7 +10,7 @@ - + diff --git a/Plugins/IW4ScriptCommands/IW4ScriptCommands.csproj b/Plugins/IW4ScriptCommands/IW4ScriptCommands.csproj index 8c371e527..2c925e28a 100644 --- a/Plugins/IW4ScriptCommands/IW4ScriptCommands.csproj +++ b/Plugins/IW4ScriptCommands/IW4ScriptCommands.csproj @@ -10,7 +10,7 @@ - + diff --git a/Plugins/LiveRadar/LiveRadar.csproj b/Plugins/LiveRadar/LiveRadar.csproj index efd9d1d91..7f0665731 100644 --- a/Plugins/LiveRadar/LiveRadar.csproj +++ b/Plugins/LiveRadar/LiveRadar.csproj @@ -16,7 +16,7 @@ - + diff --git a/Plugins/LiveRadar/Plugin.cs b/Plugins/LiveRadar/Plugin.cs index fbbb39309..c787a8054 100644 --- a/Plugins/LiveRadar/Plugin.cs +++ b/Plugins/LiveRadar/Plugin.cs @@ -1,11 +1,12 @@ using LiveRadar.Configuration; using SharedLibraryCore; -using SharedLibraryCore.Configuration; -using SharedLibraryCore.Interfaces; using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using SharedLibraryCore.Interfaces; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace LiveRadar { @@ -21,11 +22,13 @@ namespace LiveRadar private readonly Dictionary _botGuidLookups; private bool addedPage; private readonly object lockObject = new object(); + private readonly ILogger _logger; - public Plugin(IConfigurationHandlerFactory configurationHandlerFactory) + public Plugin(ILogger logger, IConfigurationHandlerFactory configurationHandlerFactory) { _configurationHandler = configurationHandlerFactory.GetConfigurationHandler("LiveRadarConfiguration"); _botGuidLookups = new Dictionary(); + _logger = logger; } public Task OnEventAsync(GameEvent E, Server S) @@ -80,8 +83,7 @@ namespace LiveRadar catch (Exception e) { - S.Logger.WriteWarning($"Could not parse live radar output: {e.Data}"); - S.Logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogError(e, "Could not parse live radar output: {data}", e.Data); } } diff --git a/Plugins/Login/Login.csproj b/Plugins/Login/Login.csproj index c43bfe7df..49933244e 100644 --- a/Plugins/Login/Login.csproj +++ b/Plugins/Login/Login.csproj @@ -23,7 +23,7 @@ - + diff --git a/Plugins/ProfanityDeterment/ProfanityDeterment.csproj b/Plugins/ProfanityDeterment/ProfanityDeterment.csproj index 3b98cd452..1a8aa316f 100644 --- a/Plugins/ProfanityDeterment/ProfanityDeterment.csproj +++ b/Plugins/ProfanityDeterment/ProfanityDeterment.csproj @@ -16,7 +16,7 @@ - + diff --git a/Plugins/ScriptPlugins/ParserIW6x.js b/Plugins/ScriptPlugins/ParserIW6x.js index facfedab3..a9133446e 100644 --- a/Plugins/ScriptPlugins/ParserIW6x.js +++ b/Plugins/ScriptPlugins/ParserIW6x.js @@ -21,7 +21,7 @@ var plugin = { rconParser.Configuration.CommandPrefixes.TempBan = 'clientkick {0} "{1}"'; rconParser.Configuration.CommandPrefixes.RConResponse = '\xff\xff\xff\xffprint\n'; rconParser.Configuration.Dvar.Pattern = '^ *\\"(.+)\\" is: \\"(.+)?\\" default: \\"(.+)?\\"\\n(?:latched: \\"(.+)?\\"\\n)? *(.+)$'; - rconParser.Configuration.Status.Pattern = '^ *([0-9]+) +-?([0-9]+) +(Yes|No) +((?:[A-Z]+|[0-9]+)) +((?:[a-z]|[0-9]){8,32}|(?:[a-z]|[0-9]){8,32}|bot[0-9]+|(?:[0-9]+)) *(.{0,32}) +(\d+\.\d+\.\d+.\d+\:-*\d{1,5}|0+.0+:-*\d{1,5}|loopback|unknown|bot) +(-*[0-9]+) *$'; + rconParser.Configuration.Status.Pattern = '^ *([0-9]+) +-?([0-9]+) +(Yes|No) +((?:[A-Z]+|[0-9]+)) +((?:[a-z]|[0-9]){8,32}|(?:[a-z]|[0-9]){8,32}|bot[0-9]+|(?:[0-9]+)) *(.{0,32}) +(\\d+\\.\\d+\\.\\d+.\\d+\\:-*\\d{1,5}|0+.0+:-*\\d{1,5}|loopback|unknown|bot) +(-*[0-9]+) *$'; rconParser.Configuration.StatusHeader.Pattern = 'num +score +bot +ping +guid +name +address +qport *'; rconParser.Configuration.WaitForResponse = false; rconParser.Configuration.Status.AddMapping(102, 4); diff --git a/Plugins/ScriptPlugins/SampleScriptPluginCommand.js b/Plugins/ScriptPlugins/SampleScriptPluginCommand.js index b02f92382..63929aa35 100644 --- a/Plugins/ScriptPlugins/SampleScriptPluginCommand.js +++ b/Plugins/ScriptPlugins/SampleScriptPluginCommand.js @@ -27,6 +27,7 @@ let commands = [{ // we want to print out a pong message for the number of times they requested for (var i = 0; i < times; i++) { + gameEvent.Origin = undefined; gameEvent.Origin.Tell(`^${i}pong #${i + 1}^7`); // don't want to wait if it's the last pong diff --git a/Plugins/Stats/Cheat/Detection.cs b/Plugins/Stats/Cheat/Detection.cs index bf689db6a..f5357939a 100644 --- a/Plugins/Stats/Cheat/Detection.cs +++ b/Plugins/Stats/Cheat/Detection.cs @@ -1,13 +1,13 @@ using IW4MAdmin.Plugins.Stats.Models; -using SharedLibraryCore; using SharedLibraryCore.Database.Models; using SharedLibraryCore.Helpers; using SharedLibraryCore.Interfaces; using System; using System.Collections.Generic; using System.Linq; -using System.Text; using System.Text.RegularExpressions; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Plugins.Stats.Cheat { @@ -223,11 +223,6 @@ namespace IW4MAdmin.Plugins.Stats.Cheat if (weightedSessionAverage > Thresholds.MaxOffset(totalSessionHits) && totalSessionHits >= (Thresholds.MediumSampleMinKills * 2)) { - Log.WriteDebug("*** Reached Max Session Average for Angle Difference ***"); - Log.WriteDebug($"Session Average = {weightedSessionAverage}"); - Log.WriteDebug($"HitCount = {HitCount}"); - Log.WriteDebug($"ID = {hit.AttackerId}"); - results.Add(new DetectionPenaltyResult() { ClientPenalty = EFPenalty.PenaltyType.Ban, @@ -237,18 +232,14 @@ namespace IW4MAdmin.Plugins.Stats.Cheat Location = hitLoc.Location }); } - -#if DEBUG - Log.WriteDebug($"PredictVsReal={realAgainstPredict}"); -#endif + + Log.LogDebug("PredictVsReal={realAgainstPredict}", realAgainstPredict); } #endregion #region STRAIN double currentStrain = Strain.GetStrain(hit.Distance / 0.0254, hit.ViewAngles, Math.Max(50, LastOffset == 0 ? 50 : (hit.TimeOffset - LastOffset))); -#if DEBUG == true - Log.WriteDebug($"Current Strain: {currentStrain}"); -#endif + Log.LogDebug("Current Strain: {currentStrain}", currentStrain); LastOffset = hit.TimeOffset; if (currentStrain > ClientStats.MaxStrain) diff --git a/Plugins/Stats/Cheat/Strain.cs b/Plugins/Stats/Cheat/Strain.cs index 3f4fc01ab..7fe4b1d53 100644 --- a/Plugins/Stats/Cheat/Strain.cs +++ b/Plugins/Stats/Cheat/Strain.cs @@ -27,12 +27,6 @@ namespace IW4MAdmin.Plugins.Stats.Cheat double[] distance = Utilities.AngleStuff(newAngle, LastAngle); LastDistance = distance[0] + distance[1]; -#if DEBUG == true - Console.WriteLine($"Angle Between = {LastDistance}"); - Console.WriteLine($"Distance From Target = {killDistance}"); - Console.WriteLine($"Time Offset = {deltaTime}"); - Console.WriteLine($"Decay Factor = {decayFactor} "); -#endif // this happens on first kill if ((distance[0] == 0 && distance[1] == 0) || deltaTime == 0 || diff --git a/Plugins/Stats/Helpers/MigrationHelper.cs b/Plugins/Stats/Helpers/MigrationHelper.cs new file mode 100644 index 000000000..e63638df0 --- /dev/null +++ b/Plugins/Stats/Helpers/MigrationHelper.cs @@ -0,0 +1,7 @@ +namespace Stats.Helpers +{ + public class MigrationHelper + { + + } +} \ No newline at end of file diff --git a/Plugins/Stats/Helpers/StatManager.cs b/Plugins/Stats/Helpers/StatManager.cs index ff33e9910..e6a4d9334 100644 --- a/Plugins/Stats/Helpers/StatManager.cs +++ b/Plugins/Stats/Helpers/StatManager.cs @@ -4,7 +4,6 @@ using IW4MAdmin.Plugins.Stats.Models; using IW4MAdmin.Plugins.Stats.Web.Dtos; using Microsoft.EntityFrameworkCore; using SharedLibraryCore; -using SharedLibraryCore.Database; using SharedLibraryCore.Database.Models; using SharedLibraryCore.Helpers; using SharedLibraryCore.Interfaces; @@ -15,7 +14,9 @@ using System.Linq; using System.Linq.Expressions; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using static IW4MAdmin.Plugins.Stats.Cheat.Detection; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Plugins.Stats.Helpers { @@ -30,10 +31,10 @@ namespace IW4MAdmin.Plugins.Stats.Helpers public static string CLIENT_STATS_KEY = "ClientStats"; public static string CLIENT_DETECTIONS_KEY = "ClientDetections"; - public StatManager(IManager mgr, IDatabaseContextFactory contextFactory, IConfigurationHandler configHandler) + public StatManager(ILogger logger, IManager mgr, IDatabaseContextFactory contextFactory, IConfigurationHandler configHandler) { _servers = new ConcurrentDictionary(); - _log = mgr.GetLogger(0); + _log = logger; _contextFactory = contextFactory; _configHandler = configHandler; } @@ -265,8 +266,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers catch (Exception e) { - _log.WriteError($"{Utilities.CurrentLocalization.LocalizationIndex["PLUGIN_STATS_ERROR_ADD"]} - {e.Message}"); - _log.WriteDebug(e.GetExceptionInfo()); + _log.LogError(e, "{message}", Utilities.CurrentLocalization.LocalizationIndex["PLUGIN_STATS_ERROR_ADD"]); } } @@ -283,7 +283,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers if (!_servers.ContainsKey(serverId)) { - _log.WriteError($"[Stats::AddPlayer] Server with id {serverId} could not be found"); + _log.LogError("[Stats::AddPlayer] Server with id {serverId} could not be found", serverId); return null; } @@ -360,7 +360,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers clientStats.LastScore = pl.Score; pl.SetAdditionalProperty(CLIENT_DETECTIONS_KEY, new Detection(_log, clientStats)); - pl.CurrentServer.Logger.WriteInfo($"Added {pl} to stats"); + _log.LogDebug("Added {client} to stats", pl.ToString()); } return clientStats; @@ -368,8 +368,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers catch (Exception ex) { - _log.WriteWarning("Could not add client to stats"); - _log.WriteDebug(ex.GetExceptionInfo()); + _log.LogError(ex, "Could not add client to stats {@client}", pl); } return null; @@ -382,11 +381,11 @@ namespace IW4MAdmin.Plugins.Stats.Helpers /// public async Task RemovePlayer(EFClient pl) { - pl.CurrentServer.Logger.WriteInfo($"Removing {pl} from stats"); + _log.LogDebug("Removing {client} from stats", pl.ToString()); if (pl.CurrentServer == null) { - pl.CurrentServer.Logger.WriteWarning($"Disconnecting client {pl} is not on a server, state is {pl.State}"); + _log.LogWarning("Disconnecting client {@client} is not on a server", pl); return; } @@ -407,7 +406,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers else { - pl.CurrentServer.Logger.WriteWarning($"Disconnecting client {pl} has not been added to stats, state is {pl.State}"); + _log.LogWarning("Disconnecting client {@client} has not been added to stats", pl); } } @@ -452,10 +451,9 @@ namespace IW4MAdmin.Plugins.Stats.Helpers } } - catch (FormatException) + catch (FormatException ex) { - _log.WriteError("Could not parse vector data from hit"); - _log.WriteDebug($"Kill - {killOrigin} Death - {deathOrigin} ViewAngle - {viewAngles} Snapshot - {string.Join(",", snapshotAngles.Select(_a => _a.ToString()))}"); + _log.LogWarning(ex, "Could not parse vector data from hit"); return; } @@ -527,8 +525,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers catch (Exception e) { - _log.WriteError("Could not store client kills"); - _log.WriteDebug(e.GetExceptionInfo()); + _log.LogError(e, "Could not store client kills"); } finally @@ -583,9 +580,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers catch (TaskCanceledException) { } catch (Exception ex) { - _log.WriteError("Could not save hit or AC info"); - _log.WriteDebug(ex.GetExceptionInfo()); - _log.WriteDebug($"Attacker: {attacker} Victim: {victim}, ServerId {serverId}"); + _log.LogError(ex, "Could not save hit or anti-cheat info {@attacker} {@victim} {server}", attacker, victim, serverId); } finally @@ -714,9 +709,6 @@ namespace IW4MAdmin.Plugins.Stats.Helpers var attackerStats = attacker.GetAdditionalProperty(CLIENT_STATS_KEY); var victimStats = victim.GetAdditionalProperty(CLIENT_STATS_KEY); -#if DEBUG - _log.WriteDebug("Processing standard kill"); -#endif // update the total stats _servers[serverId].ServerStatistics.TotalKills += 1; @@ -754,14 +746,14 @@ namespace IW4MAdmin.Plugins.Stats.Helpers // fixme: why? if (double.IsNaN(victimStats.SPM) || double.IsNaN(victimStats.Skill)) { - _log.WriteDebug($"[StatManager::AddStandardKill] victim SPM/SKILL {victimStats.SPM} {victimStats.Skill}"); + _log.LogWarning("victim SPM/SKILL {@victimStats}", victimStats); victimStats.SPM = 0.0; victimStats.Skill = 0.0; } if (double.IsNaN(attackerStats.SPM) || double.IsNaN(attackerStats.Skill)) { - _log.WriteDebug($"[StatManager::AddStandardKill] attacker SPM/SKILL {victimStats.SPM} {victimStats.Skill}"); + _log.LogWarning("attacker SPM/SKILL {@attackerStats}", attackerStats); attackerStats.SPM = 0.0; attackerStats.Skill = 0.0; } @@ -781,8 +773,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers catch (Exception e) { - _log.WriteWarning($"Could not update stat history for {attacker}"); - _log.WriteDebug(e.GetExceptionInfo()); + _log.LogWarning(e, "Could not update stat history for {attacker}", attacker.ToString()); } finally @@ -1099,8 +1090,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers if (clientStats.SPM < 0) { - _log.WriteWarning("[StatManager:UpdateStats] clientStats SPM < 0"); - _log.WriteDebug($"{scoreDifference}-{clientStats.RoundScore} - {clientStats.LastScore} - {clientStats.SessionScore}"); + _log.LogWarning("clientStats SPM < 0 {scoreDifference} {@clientStats}", scoreDifference, clientStats); clientStats.SPM = 0; } @@ -1110,8 +1100,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers // fixme: how does this happen? if (double.IsNaN(clientStats.SPM) || double.IsNaN(clientStats.Skill)) { - _log.WriteWarning("[StatManager::UpdateStats] clientStats SPM/Skill NaN"); - _log.WriteDebug($"{killSPM}-{KDRWeight}-{totalPlayTime}-{SPMAgainstPlayWeight}-{clientStats.SPM}-{clientStats.Skill}-{scoreDifference}"); + _log.LogWarning("clientStats SPM/Skill NaN {@killInfo}", new {killSPM, KDRWeight, totalPlayTime, SPMAgainstPlayWeight, clientStats, scoreDifference}); clientStats.SPM = 0; clientStats.Skill = 0; } @@ -1133,7 +1122,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers if (serverStats == null) { - _log.WriteDebug($"Initializing server stats for {serverId}"); + _log.LogDebug("Initializing server stats for {serverId}", serverId); // server stats have never been generated before serverStats = new EFServerStatistics() { @@ -1225,8 +1214,7 @@ namespace IW4MAdmin.Plugins.Stats.Helpers catch (Exception e) { - _log.WriteError("There was a probably syncing server stats"); - _log.WriteDebug(e.GetExceptionInfo()); + _log.LogError(e, "There was a problem syncing server stats"); } finally diff --git a/Plugins/Stats/Plugin.cs b/Plugins/Stats/Plugin.cs index 995eacf86..3cccb07f9 100644 --- a/Plugins/Stats/Plugin.cs +++ b/Plugins/Stats/Plugin.cs @@ -14,6 +14,7 @@ using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; namespace IW4MAdmin.Plugins.Stats { @@ -28,23 +29,24 @@ namespace IW4MAdmin.Plugins.Stats public static StatManager Manager { get; private set; } public static IManager ServerManager; public static IConfigurationHandler Config { get; private set; } -#if DEBUG - int scriptDamageCount; - int scriptKillCount; -#endif + private readonly IDatabaseContextFactory _databaseContextFactory; private readonly ITranslationLookup _translationLookup; private readonly IMetaService _metaService; private readonly IResourceQueryHelper _chatQueryHelper; + private readonly ILogger _managerLogger; + private readonly ILogger _logger; - public Plugin(IConfigurationHandlerFactory configurationHandlerFactory, IDatabaseContextFactory databaseContextFactory, - ITranslationLookup translationLookup, IMetaService metaService, IResourceQueryHelper chatQueryHelper) + public Plugin(ILogger logger, IConfigurationHandlerFactory configurationHandlerFactory, IDatabaseContextFactory databaseContextFactory, + ITranslationLookup translationLookup, IMetaService metaService, IResourceQueryHelper chatQueryHelper, ILogger managerLogger) { Config = configurationHandlerFactory.GetConfigurationHandler("StatsPluginSettings"); _databaseContextFactory = databaseContextFactory; _translationLookup = translationLookup; _metaService = metaService; _chatQueryHelper = chatQueryHelper; + _managerLogger = managerLogger; + _logger = logger; } public async Task OnEventAsync(GameEvent E, Server S) @@ -102,23 +104,13 @@ namespace IW4MAdmin.Plugins.Stats { E.Origin = E.Target; } - -#if DEBUG - scriptKillCount++; - S.Logger.WriteInfo($"Start ScriptKill {scriptKillCount}"); -#endif - await Manager.AddScriptHit(false, E.Time, E.Origin, E.Target, StatManager.GetIdForServer(S), S.CurrentMap.Name, killInfo[7], killInfo[8], killInfo[5], killInfo[6], killInfo[3], killInfo[4], killInfo[9], killInfo[10], killInfo[11], killInfo[12], killInfo[13], killInfo[14], killInfo[15], killInfo[16], killInfo[17]); - -#if DEBUG - S.Logger.WriteInfo($"End ScriptKill {scriptKillCount}"); -#endif } else { - S.Logger.WriteDebug("Skipping script kill as it is ignored or data in customcallbacks is outdated/missing"); + _logger.LogDebug("Skipping script kill as it is ignored or data in customcallbacks is outdated/missing"); } break; case GameEvent.EventType.Kill: @@ -155,22 +147,13 @@ namespace IW4MAdmin.Plugins.Stats E.Origin = E.Target; } -#if DEBUG - scriptDamageCount++; - S.Logger.WriteInfo($"Start ScriptDamage {scriptDamageCount}"); -#endif - await Manager.AddScriptHit(true, E.Time, E.Origin, E.Target, StatManager.GetIdForServer(S), S.CurrentMap.Name, killInfo[7], killInfo[8], killInfo[5], killInfo[6], killInfo[3], killInfo[4], killInfo[9], killInfo[10], killInfo[11], killInfo[12], killInfo[13], killInfo[14], killInfo[15], killInfo[16], killInfo[17]); - -#if DEBUG - S.Logger.WriteInfo($"End ScriptDamage {scriptDamageCount}"); -#endif } else { - S.Logger.WriteDebug("Skipping script damage as it is ignored or data in customcallbacks is outdated/missing"); + _logger.LogDebug("Skipping script damage as it is ignored or data in customcallbacks is outdated/missing"); } break; } @@ -457,7 +440,7 @@ namespace IW4MAdmin.Plugins.Stats manager.GetMessageTokens().Add(new MessageToken("MOSTKILLS", mostKills)); ServerManager = manager; - Manager = new StatManager(manager, _databaseContextFactory, Config); + Manager = new StatManager(_managerLogger, manager, _databaseContextFactory, Config); } public Task OnTickAsync(Server S) diff --git a/Plugins/Stats/Stats.csproj b/Plugins/Stats/Stats.csproj index 879a9535b..1c379fca9 100644 --- a/Plugins/Stats/Stats.csproj +++ b/Plugins/Stats/Stats.csproj @@ -13,13 +13,15 @@ 2018 Debug;Release;Prerelease 8.0 + false - + + diff --git a/Plugins/Web/StatsWeb/API/StatsController.cs b/Plugins/Web/StatsWeb/API/StatsController.cs index 483918615..9b2e72cf0 100644 --- a/Plugins/Web/StatsWeb/API/StatsController.cs +++ b/Plugins/Web/StatsWeb/API/StatsController.cs @@ -1,11 +1,12 @@ using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; -using SharedLibraryCore; using SharedLibraryCore.Dtos; using SharedLibraryCore.Interfaces; using Stats.Dtos; using System; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace StatsWeb.API { @@ -16,7 +17,7 @@ namespace StatsWeb.API private readonly ILogger _logger; private readonly IResourceQueryHelper _statsQueryHelper; - public StatsController(ILogger logger, IResourceQueryHelper statsQueryHelper) + public StatsController(ILogger logger, IResourceQueryHelper statsQueryHelper) { _statsQueryHelper = statsQueryHelper; _logger = logger; @@ -56,8 +57,7 @@ namespace StatsWeb.API catch (Exception e) { - _logger.WriteWarning($"Could not get client stats for client id {clientId}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Could not get client stats for client id {clientId}", clientId); return StatusCode(StatusCodes.Status500InternalServerError, new ErrorResponse { diff --git a/Plugins/Web/StatsWeb/ChatResourceQueryHelper.cs b/Plugins/Web/StatsWeb/ChatResourceQueryHelper.cs index cb5bed5e7..7af3cfcc0 100644 --- a/Plugins/Web/StatsWeb/ChatResourceQueryHelper.cs +++ b/Plugins/Web/StatsWeb/ChatResourceQueryHelper.cs @@ -10,6 +10,8 @@ using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace StatsWeb { @@ -23,7 +25,7 @@ namespace StatsWeb private readonly ApplicationConfiguration _appConfig; private List serverCache; - public ChatResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory, ApplicationConfiguration appConfig) + public ChatResourceQueryHelper(ILogger logger, IDatabaseContextFactory contextFactory, ApplicationConfiguration appConfig) { _contextFactory = contextFactory; _logger = logger; diff --git a/Plugins/Web/StatsWeb/Controllers/StatsController.cs b/Plugins/Web/StatsWeb/Controllers/StatsController.cs index 77a0a0e80..1fa81696a 100644 --- a/Plugins/Web/StatsWeb/Controllers/StatsController.cs +++ b/Plugins/Web/StatsWeb/Controllers/StatsController.cs @@ -12,6 +12,8 @@ using StatsWeb.Extensions; using System; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace IW4MAdmin.Plugins.Web.StatsWeb.Controllers { @@ -22,7 +24,7 @@ namespace IW4MAdmin.Plugins.Web.StatsWeb.Controllers private readonly IResourceQueryHelper _chatResourceQueryHelper; private readonly ITranslationLookup _translationLookup; - public StatsController(ILogger logger, IManager manager, IResourceQueryHelper resourceQueryHelper, + public StatsController(ILogger logger, IManager manager, IResourceQueryHelper resourceQueryHelper, ITranslationLookup translationLookup) : base(manager) { _logger = logger; @@ -108,15 +110,13 @@ namespace IW4MAdmin.Plugins.Web.StatsWeb.Controllers catch (ArgumentException e) { - _logger.WriteWarning($"Could not parse chat message search query - {query}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Could not parse chat message search query {query}", query); ViewBag.Error = e; } catch (FormatException e) { - _logger.WriteWarning($"Could not parse chat message search query filter format - {query}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Could not parse chat message search query filter format {query}", query); ViewBag.Error = e; } @@ -136,15 +136,13 @@ namespace IW4MAdmin.Plugins.Web.StatsWeb.Controllers catch (ArgumentException e) { - _logger.WriteWarning($"Could not parse chat message search query - {query}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Could not parse chat message search query {query}", query); throw; } catch (FormatException e) { - _logger.WriteWarning($"Could not parse chat message search query filter format - {query}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Could not parse chat message search query filter format {query}", query); throw; } diff --git a/Plugins/Web/StatsWeb/StatsWeb.csproj b/Plugins/Web/StatsWeb/StatsWeb.csproj index b7ce2d2df..75017f636 100644 --- a/Plugins/Web/StatsWeb/StatsWeb.csproj +++ b/Plugins/Web/StatsWeb/StatsWeb.csproj @@ -14,7 +14,7 @@ Always - + @@ -28,7 +28,7 @@ Never - + diff --git a/Plugins/Welcome/Welcome.csproj b/Plugins/Welcome/Welcome.csproj index 02dc83ee4..ebdc6a2e9 100644 --- a/Plugins/Welcome/Welcome.csproj +++ b/Plugins/Welcome/Welcome.csproj @@ -16,7 +16,7 @@ - + diff --git a/SharedLibraryCore/Command.cs b/SharedLibraryCore/Command.cs index 2f0c5e5f4..5a8b788de 100644 --- a/SharedLibraryCore/Command.cs +++ b/SharedLibraryCore/Command.cs @@ -6,6 +6,7 @@ using SharedLibraryCore.Configuration; using SharedLibraryCore.Database.Models; using SharedLibraryCore.Interfaces; using static SharedLibraryCore.Server; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace SharedLibraryCore { diff --git a/SharedLibraryCore/Commands/NativeCommands.cs b/SharedLibraryCore/Commands/NativeCommands.cs index 9d47a2cf0..7429f16b7 100644 --- a/SharedLibraryCore/Commands/NativeCommands.cs +++ b/SharedLibraryCore/Commands/NativeCommands.cs @@ -12,6 +12,8 @@ using System.Security.Cryptography; using System.Text; using System.Text.RegularExpressions; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; using static SharedLibraryCore.Database.Models.EFClient; namespace SharedLibraryCore.Commands @@ -646,7 +648,7 @@ namespace SharedLibraryCore.Commands /// public class SetLevelCommand : Command { - public SetLevelCommand(CommandConfiguration config, ITranslationLookup translationLookup, ILogger logger) : base(config, translationLookup) + public SetLevelCommand(CommandConfiguration config, ITranslationLookup translationLookup, ILogger logger) : base(config, translationLookup) { Name = "setlevel"; Description = _translationLookup["COMMANDS_SETLEVEL_DESC"]; @@ -727,13 +729,16 @@ namespace SharedLibraryCore.Commands gameEvent.Owner.Manager.GetActiveClients() .FirstOrDefault(c => c.ClientId == targetClient?.ClientId) ?? targetClient : targetClient; - logger.WriteInfo($"Beginning set level of client {gameEvent.Origin} to {newPerm}"); + logger.LogDebug("Beginning set level of client {origin} to {newPermission}", gameEvent.Origin.ToString(), newPerm); var result = await targetClient.SetLevel(newPerm, gameEvent.Origin).WaitAsync(Utilities.DefaultCommandTimeout, gameEvent.Owner.Manager.CancellationToken); if (result.Failed) { - logger.WriteInfo($"Failed to set level of client {gameEvent.Origin}"); + using (LogContext.PushProperty("Server", gameEvent.Origin.CurrentServer?.ToString())) + { + logger.LogWarning("Failed to set level of client {origin}", gameEvent.Origin.ToString()); + } gameEvent.Origin.Tell(_translationLookup["SERVER_ERROR_COMMAND_INGAME"]); return; } diff --git a/SharedLibraryCore/Events/GameEvent.cs b/SharedLibraryCore/Events/GameEvent.cs index 40586d389..293d44651 100644 --- a/SharedLibraryCore/Events/GameEvent.cs +++ b/SharedLibraryCore/Events/GameEvent.cs @@ -3,6 +3,8 @@ using SharedLibraryCore.Events; using System; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; namespace SharedLibraryCore { @@ -254,9 +256,6 @@ namespace SharedLibraryCore public void Complete() { _eventFinishedWaiter.Set(); -#if DEBUG - Owner?.Logger.WriteDebug($"Completed internal for event {Id}"); -#endif } /// @@ -266,11 +265,7 @@ namespace SharedLibraryCore public async Task WaitAsync(TimeSpan timeSpan, CancellationToken token) { bool processed = false; - -#if DEBUG - Owner?.Logger.WriteDebug($"Begin wait for event {Id}"); -#endif - + Utilities.DefaultLogger.LogDebug("Begin wait for event {Id}", Id); try { processed = await Task.Run(() => _eventFinishedWaiter.WaitOne(timeSpan), token); @@ -283,14 +278,12 @@ namespace SharedLibraryCore if (!processed) { - Owner?.Logger.WriteError("Waiting for event to complete timed out"); - Owner?.Logger.WriteDebug($"{Id}, {Type}, {Data}, {Extra}, {FailReason.ToString()}, {Message}, {Origin}, {Target}"); -#if DEBUG - //throw new Exception(); -#endif + using(LogContext.PushProperty("Server", Owner?.ToString())) + { + Utilities.DefaultLogger.LogError("Waiting for event to complete timed out {@eventData}", new { Event = this, Message, Origin = Origin.ToString(), Target = Target.ToString()}); + } } - // this lets us know if the the action timed out FailReason = FailReason == EventFailReason.None && !processed ? EventFailReason.Timeout : FailReason; return this; diff --git a/SharedLibraryCore/Exceptions/RConException.cs b/SharedLibraryCore/Exceptions/RConException.cs new file mode 100644 index 000000000..e5f993e24 --- /dev/null +++ b/SharedLibraryCore/Exceptions/RConException.cs @@ -0,0 +1,11 @@ +using System; + +namespace SharedLibraryCore.Exceptions +{ + public class RConException : Exception + { + public RConException(string message) : base(message) + { + } + } +} \ No newline at end of file diff --git a/SharedLibraryCore/Interfaces/ILogger.cs b/SharedLibraryCore/Interfaces/ILogger.cs index 57049b526..5afb04b86 100644 --- a/SharedLibraryCore/Interfaces/ILogger.cs +++ b/SharedLibraryCore/Interfaces/ILogger.cs @@ -1,11 +1,8 @@ using System; -using System.Collections.Generic; -using System.Linq; -using System.Text; -using System.Threading.Tasks; namespace SharedLibraryCore.Interfaces { + [Obsolete] public interface ILogger { void WriteVerbose(string msg); diff --git a/SharedLibraryCore/Interfaces/IManager.cs b/SharedLibraryCore/Interfaces/IManager.cs index 95bf4b882..8153e6cef 100644 --- a/SharedLibraryCore/Interfaces/IManager.cs +++ b/SharedLibraryCore/Interfaces/IManager.cs @@ -6,6 +6,7 @@ using SharedLibraryCore.Database.Models; using System.Threading; using System.Collections; using System; +using Microsoft.Extensions.Logging; namespace SharedLibraryCore.Interfaces { @@ -15,6 +16,7 @@ namespace SharedLibraryCore.Interfaces Task Start(); void Stop(); void Restart(); + [Obsolete] ILogger GetLogger(long serverId); IList GetServers(); IList GetCommands(); diff --git a/SharedLibraryCore/PartialEntities/EFClient.cs b/SharedLibraryCore/PartialEntities/EFClient.cs index ee6234d40..2782ed38e 100644 --- a/SharedLibraryCore/PartialEntities/EFClient.cs +++ b/SharedLibraryCore/PartialEntities/EFClient.cs @@ -8,6 +8,8 @@ using System.Text.Json.Serialization; using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; namespace SharedLibraryCore.Database.Models { @@ -89,6 +91,7 @@ namespace SharedLibraryCore.Database.Models SetAdditionalProperty("_reportCount", 0); ReceivedPenalties = new List(); _processingEvent = new SemaphoreSlim(1, 1); + } ~EFClient() @@ -475,39 +478,42 @@ namespace SharedLibraryCore.Database.Models { var loc = Utilities.CurrentLocalization.LocalizationIndex; - if (string.IsNullOrWhiteSpace(Name) || CleanedName.Replace(" ", "").Length < 3) + using (LogContext.PushProperty("Server", CurrentServer?.ToString())) { - CurrentServer.Logger.WriteDebug($"Kicking {this} because their name is too short"); - Kick(loc["SERVER_KICK_MINNAME"], Utilities.IW4MAdminClient(CurrentServer)); - return false; - } + if (string.IsNullOrWhiteSpace(Name) || CleanedName.Replace(" ", "").Length < 3) + { + Utilities.DefaultLogger.LogInformation("Kicking {client} because their name is too short", ToString()); + Kick(loc["SERVER_KICK_MINNAME"], Utilities.IW4MAdminClient(CurrentServer)); + return false; + } - if (CurrentServer.Manager.GetApplicationSettings().Configuration() - .DisallowedClientNames - ?.Any(_name => Regex.IsMatch(Name, _name)) ?? false) - { - CurrentServer.Logger.WriteDebug($"Kicking {this} because their name is not allowed"); - Kick(loc["SERVER_KICK_GENERICNAME"], Utilities.IW4MAdminClient(CurrentServer)); - return false; - } + if (CurrentServer.Manager.GetApplicationSettings().Configuration() + .DisallowedClientNames + ?.Any(_name => Regex.IsMatch(Name, _name)) ?? false) + { + Utilities.DefaultLogger.LogInformation("Kicking {client} because their name is not allowed", ToString()); + Kick(loc["SERVER_KICK_GENERICNAME"], Utilities.IW4MAdminClient(CurrentServer)); + return false; + } - if (Name.Where(c => char.IsControl(c)).Count() > 0) - { - CurrentServer.Logger.WriteDebug($"Kicking {this} because their name contains control characters"); - Kick(loc["SERVER_KICK_CONTROLCHARS"], Utilities.IW4MAdminClient(CurrentServer)); - return false; - } + if (Name.Where(c => char.IsControl(c)).Count() > 0) + { + Utilities.DefaultLogger.LogInformation("Kicking {client} because their name contains control characters", ToString()); + Kick(loc["SERVER_KICK_CONTROLCHARS"], Utilities.IW4MAdminClient(CurrentServer)); + return false; + } - // reserved slots stuff - // todo: bots don't seem to honor party_maxplayers/sv_maxclients - if (CurrentServer.MaxClients - (CurrentServer.GetClientsAsList().Count(_client => !_client.IsPrivileged() && !_client.IsBot)) < CurrentServer.ServerConfig.ReservedSlotNumber && - !this.IsPrivileged() && - CurrentServer.GetClientsAsList().Count <= CurrentServer.MaxClients && - CurrentServer.MaxClients != 0) - { - CurrentServer.Logger.WriteDebug($"Kicking {this} their spot is reserved"); - Kick(loc["SERVER_KICK_SLOT_IS_RESERVED"], Utilities.IW4MAdminClient(CurrentServer)); - return false; + // reserved slots stuff + // todo: bots don't seem to honor party_maxplayers/sv_maxclients + if (CurrentServer.MaxClients - (CurrentServer.GetClientsAsList().Count(_client => !_client.IsPrivileged() && !_client.IsBot)) < CurrentServer.ServerConfig.ReservedSlotNumber && + !this.IsPrivileged() && + CurrentServer.GetClientsAsList().Count <= CurrentServer.MaxClients && + CurrentServer.MaxClients != 0) + { + Utilities.DefaultLogger.LogInformation("Kicking {client} their spot is reserved", ToString()); + Kick(loc["SERVER_KICK_SLOT_IS_RESERVED"], Utilities.IW4MAdminClient(CurrentServer)); + return false; + } } return true; @@ -515,126 +521,151 @@ namespace SharedLibraryCore.Database.Models public async Task OnDisconnect() { - TotalConnectionTime += ConnectionLength; - LastConnection = DateTime.UtcNow; - - try + using (LogContext.PushProperty("Server", CurrentServer?.ToString())) { - await CurrentServer.Manager.GetClientService().Update(this); - } + TotalConnectionTime += ConnectionLength; + LastConnection = DateTime.UtcNow; - catch (Exception e) - { - CurrentServer.Logger.WriteWarning($"Could not update disconnected player {this}"); - CurrentServer.Logger.WriteDebug(e.GetExceptionInfo()); - } + Utilities.DefaultLogger.LogInformation("Client {client} is leaving the game", ToString()); - finally - { - State = ClientState.Unknown; + try + { + await CurrentServer.Manager.GetClientService().Update(this); + } + + catch (Exception e) + { + Utilities.DefaultLogger.LogError(e, "Could not update disconnected client {client}", + ToString()); + } + + finally + { + State = ClientState.Unknown; + } } } public async Task OnJoin(int? ipAddress) { - CurrentServer.Logger.WriteDebug($"Start join for {this}::{ipAddress}::{Level.ToString()}"); - - if (ipAddress != null) + using (LogContext.PushProperty("Server", CurrentServer?.ToString())) { - IPAddress = ipAddress; - await CurrentServer.Manager.GetClientService().UpdateAlias(this); - CurrentServer.Logger.WriteDebug($"Updated alias for {this}"); - await CurrentServer.Manager.GetClientService().Update(this); - CurrentServer.Logger.WriteDebug($"Updated client for {this}"); + Utilities.DefaultLogger.LogInformation("Client {client} is joining the game from {source}", ToString(), ipAddress.HasValue ? "Status" : "Log"); - bool canConnect = await CanConnect(ipAddress); - - if (!canConnect) + if (ipAddress != null) { - CurrentServer.Logger.WriteDebug($"Client {this} is not allowed to join the server"); + IPAddress = ipAddress; + Utilities.DefaultLogger.LogInformation("Received ip from client {client}", ToString()); + await CurrentServer.Manager.GetClientService().UpdateAlias(this); + await CurrentServer.Manager.GetClientService().Update(this); + + bool canConnect = await CanConnect(ipAddress); + + if (!canConnect) + { + Utilities.DefaultLogger.LogInformation("Client {client} is not allowed to join the server", + ToString()); + } + + else + { + Utilities.DefaultLogger.LogDebug("Creating join event for {client}", ToString()); + var e = new GameEvent() + { + Type = GameEvent.EventType.Join, + Origin = this, + Target = this, + Owner = CurrentServer, + }; + + CurrentServer.Manager.AddEvent(e); + } } else { - CurrentServer.Logger.WriteDebug($"Creating join event for {this}"); - var e = new GameEvent() - { - Type = GameEvent.EventType.Join, - Origin = this, - Target = this, - Owner = CurrentServer, - }; - - CurrentServer.Manager.AddEvent(e); + Utilities.DefaultLogger.LogInformation("Waiting to receive ip from client {client}", ToString()); } - } - else - { - CurrentServer.Logger.WriteDebug($"Client {this} does not have an IP yet"); + Utilities.DefaultLogger.LogDebug("OnJoin finished for {client}", ToString()); } - - CurrentServer.Logger.WriteDebug($"OnJoin finished for {this}"); } public async Task CanConnect(int? ipAddress) { - var loc = Utilities.CurrentLocalization.LocalizationIndex; - var autoKickClient = Utilities.IW4MAdminClient(CurrentServer); - - bool isAbleToConnectSimple = IsAbleToConnectSimple(); - - if (!isAbleToConnectSimple) + using (LogContext.PushProperty("Server", CurrentServer?.ToString())) { - return false; - } + var loc = Utilities.CurrentLocalization.LocalizationIndex; + var autoKickClient = Utilities.IW4MAdminClient(CurrentServer); - // we want to get any penalties that are tied to their IP or AliasLink (but not necessarily their GUID) - var activePenalties = await CurrentServer.Manager.GetPenaltyService().GetActivePenaltiesAsync(AliasLinkId, ipAddress); - var banPenalty = activePenalties.FirstOrDefault(_penalty => _penalty.Type == EFPenalty.PenaltyType.Ban); - var tempbanPenalty = activePenalties.FirstOrDefault(_penalty => _penalty.Type == EFPenalty.PenaltyType.TempBan); - var flagPenalty = activePenalties.FirstOrDefault(_penalty => _penalty.Type == EFPenalty.PenaltyType.Flag); + bool isAbleToConnectSimple = IsAbleToConnectSimple(); - // we want to kick them if any account is banned - if (banPenalty != null) - { - if (Level == Permission.Banned) + if (!isAbleToConnectSimple) { - CurrentServer.Logger.WriteDebug($"Kicking {this} because they are banned"); - Kick(loc["SERVER_BAN_PREV"].FormatExt(banPenalty?.Offense), autoKickClient); return false; } - else + // we want to get any penalties that are tied to their IP or AliasLink (but not necessarily their GUID) + var activePenalties = await CurrentServer.Manager.GetPenaltyService() + .GetActivePenaltiesAsync(AliasLinkId, ipAddress); + var banPenalty = activePenalties.FirstOrDefault(_penalty => _penalty.Type == EFPenalty.PenaltyType.Ban); + var tempbanPenalty = + activePenalties.FirstOrDefault(_penalty => _penalty.Type == EFPenalty.PenaltyType.TempBan); + var flagPenalty = + activePenalties.FirstOrDefault(_penalty => _penalty.Type == EFPenalty.PenaltyType.Flag); + + // we want to kick them if any account is banned + if (banPenalty != null) { - CurrentServer.Logger.WriteDebug($"Client {this} is banned, but using a new GUID, we we're updating their level and kicking them"); - await SetLevel(Permission.Banned, autoKickClient).WaitAsync(Utilities.DefaultCommandTimeout, CurrentServer.Manager.CancellationToken); - Kick(loc["SERVER_BAN_PREV"].FormatExt(banPenalty?.Offense), autoKickClient); + if (Level == Permission.Banned) + { + Utilities.DefaultLogger.LogInformation("Kicking {client} because they are banned", ToString()); + Kick(loc["SERVER_BAN_PREV"].FormatExt(banPenalty?.Offense), autoKickClient); + return false; + } + + else + { + Utilities.DefaultLogger.LogInformation( + "Client {client} is banned, but using a new GUID, we we're updating their level and kicking them", + ToString()); + await SetLevel(Permission.Banned, autoKickClient).WaitAsync(Utilities.DefaultCommandTimeout, + CurrentServer.Manager.CancellationToken); + Kick(loc["SERVER_BAN_PREV"].FormatExt(banPenalty?.Offense), autoKickClient); + return false; + } + } + + // we want to kick them if any account is tempbanned + if (tempbanPenalty != null) + { + Utilities.DefaultLogger.LogInformation("Kicking {client} because their GUID is temporarily banned", + ToString()); + Kick( + $"{loc["SERVER_TB_REMAIN"]} ({(tempbanPenalty.Expires.Value - DateTime.UtcNow).HumanizeForCurrentCulture()} {loc["WEBFRONT_PENALTY_TEMPLATE_REMAINING"]})", + autoKickClient); return false; } - } - // we want to kick them if any account is tempbanned - if (tempbanPenalty != null) - { - CurrentServer.Logger.WriteDebug($"Kicking {this} because their GUID is temporarily banned"); - Kick($"{loc["SERVER_TB_REMAIN"]} ({(tempbanPenalty.Expires.Value - DateTime.UtcNow).HumanizeForCurrentCulture()} {loc["WEBFRONT_PENALTY_TEMPLATE_REMAINING"]})", autoKickClient); - return false; - } + // if we found a flag, we need to make sure all the accounts are flagged + if (flagPenalty != null && Level != Permission.Flagged) + { + Utilities.DefaultLogger.LogInformation( + "Flagged client {client} joining with new GUID, so we are changing their level to flagged", + ToString()); + await SetLevel(Permission.Flagged, autoKickClient).WaitAsync(Utilities.DefaultCommandTimeout, + CurrentServer.Manager.CancellationToken); + } - // if we found a flag, we need to make sure all the accounts are flagged - if (flagPenalty != null && Level != Permission.Flagged) - { - CurrentServer.Logger.WriteDebug($"Flagged client {this} joining with new GUID, so we are changing their level to flagged"); - await SetLevel(Permission.Flagged, autoKickClient).WaitAsync(Utilities.DefaultCommandTimeout, CurrentServer.Manager.CancellationToken); - } - - // remove their auto flag - if (Level == Permission.Flagged && !activePenalties.Any(_penalty => _penalty.Type == EFPenalty.PenaltyType.Flag)) - { - // remove their auto flag status after a week - CurrentServer.Logger.WriteInfo($"Unflagging {this} because the auto flag time has expired"); - Unflag(Utilities.CurrentLocalization.LocalizationIndex["SERVER_AUTOFLAG_UNFLAG"], autoKickClient); + // remove their auto flag + if (Level == Permission.Flagged && + !activePenalties.Any(_penalty => _penalty.Type == EFPenalty.PenaltyType.Flag)) + { + // remove their auto flag status after a week + Utilities.DefaultLogger.LogInformation("Unflagging {client} because the auto flag time has expired", + ToString()); + Unflag(Utilities.CurrentLocalization.LocalizationIndex["SERVER_AUTOFLAG_UNFLAG"], autoKickClient); + } } return true; diff --git a/SharedLibraryCore/RCon/StaticHelpers.cs b/SharedLibraryCore/RCon/StaticHelpers.cs index 68625a5a8..1fc58b625 100644 --- a/SharedLibraryCore/RCon/StaticHelpers.cs +++ b/SharedLibraryCore/RCon/StaticHelpers.cs @@ -56,7 +56,8 @@ namespace SharedLibraryCore.RCon 1 => TimeSpan.FromMilliseconds(550), 2 => TimeSpan.FromMilliseconds(1000), 3 => TimeSpan.FromMilliseconds(2000), - _ => TimeSpan.FromMilliseconds(5000), + 4 => TimeSpan.FromMilliseconds(5000), + _ => TimeSpan.FromMilliseconds(10000), }; } /// @@ -66,6 +67,6 @@ namespace SharedLibraryCore.RCon /// /// how many failed connection attempts before aborting connection /// - public static readonly int AllowedConnectionFails = 4; + public static readonly int AllowedConnectionFails = 5; } } diff --git a/SharedLibraryCore/Server.cs b/SharedLibraryCore/Server.cs index 2428ce302..63c7ae4a9 100644 --- a/SharedLibraryCore/Server.cs +++ b/SharedLibraryCore/Server.cs @@ -3,12 +3,14 @@ using System.Collections.Generic; using System.Linq; using System.Threading; using System.Threading.Tasks; - +using Microsoft.Extensions.Logging; +using Serilog.Context; using SharedLibraryCore.Helpers; using SharedLibraryCore.Dtos; using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; using SharedLibraryCore.Database.Models; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace SharedLibraryCore { @@ -28,14 +30,15 @@ namespace SharedLibraryCore T7 = 8 } - public Server(ServerConfiguration config, IManager mgr, IRConConnectionFactory rconConnectionFactory, IGameLogReaderFactory gameLogReaderFactory) + public Server(ILogger logger, SharedLibraryCore.Interfaces.ILogger deprecatedLogger, + ServerConfiguration config, IManager mgr, IRConConnectionFactory rconConnectionFactory, + IGameLogReaderFactory gameLogReaderFactory) { Password = config.Password; IP = config.IPAddress; Port = config.Port; Manager = mgr; - Logger = Manager.GetLogger(this.EndPoint); - Logger.WriteInfo(this.ToString()); + Logger = deprecatedLogger; ServerConfig = config; RemoteConnection = rconConnectionFactory.CreateConnection(IP, Port, Password); EventProcessing = new SemaphoreSlim(1, 1); @@ -47,6 +50,7 @@ namespace SharedLibraryCore CustomSayEnabled = Manager.GetApplicationSettings().Configuration().EnableCustomSayName; CustomSayName = Manager.GetApplicationSettings().Configuration().CustomSayName; this.gameLogReaderFactory = gameLogReaderFactory; + ServerLogger = logger; InitializeTokens(); InitializeAutoMessages(); } @@ -123,9 +127,7 @@ namespace SharedLibraryCore public GameEvent Broadcast(string message, EFClient sender = null) { string formattedMessage = string.Format(RconParser.Configuration.CommandPrefixes.Say ?? "", $"{(CustomSayEnabled && GameName == Game.IW4 ? $"{CustomSayName}: " : "")}{message.FixIW4ForwardSlash()}"); -#if DEBUG == true - Logger.WriteVerbose(message.StripColors()); -#endif + ServerLogger.LogDebug("All->" + message.StripColors()); var e = new GameEvent() { @@ -146,18 +148,27 @@ namespace SharedLibraryCore /// EFClient to send message to protected async Task Tell(string message, EFClient target) { -#if !DEBUG - string formattedMessage = string.Format(RconParser.Configuration.CommandPrefixes.Tell, target.ClientNumber, $"{(CustomSayEnabled && GameName == Game.IW4 ? $"{CustomSayName}: " : "")}{message.FixIW4ForwardSlash()}"); - if (target.ClientNumber > -1 && message.Length > 0 && target.Level != EFClient.Permission.Console) - await this.ExecuteCommandAsync(formattedMessage); -#else - Logger.WriteVerbose($"{target.ClientNumber}->{message.StripColors()}"); - await Task.CompletedTask; -#endif + if (!Utilities.IsDevelopment) + { + var formattedMessage = string.Format(RconParser.Configuration.CommandPrefixes.Tell, + target.ClientNumber, + $"{(CustomSayEnabled && GameName == Game.IW4 ? $"{CustomSayName}: " : "")}{message.FixIW4ForwardSlash()}"); + if (target.ClientNumber > -1 && message.Length > 0 && target.Level != EFClient.Permission.Console) + await this.ExecuteCommandAsync(formattedMessage); + } + else + { + ServerLogger.LogDebug("Tell[{clientNumber}]->{message}", target.ClientNumber, message.StripColors()); + } + if (target.Level == EFClient.Permission.Console) { Console.ForegroundColor = ConsoleColor.Green; + using (LogContext.PushProperty("Server", ToString())) + { + ServerLogger.LogInformation("Command output received: {message}", message); + } Console.WriteLine(message.StripColors()); Console.ForegroundColor = ConsoleColor.Gray; } @@ -280,7 +291,8 @@ namespace SharedLibraryCore // Objects public IManager Manager { get; protected set; } - public ILogger Logger { get; private set; } + [Obsolete] + public SharedLibraryCore.Interfaces.ILogger Logger { get; private set; } public ServerConfiguration ServerConfig { get; private set; } public List Maps { get; protected set; } = new List(); public List Reports { get; set; } @@ -319,6 +331,7 @@ namespace SharedLibraryCore public string IP { get; protected set; } public string Version { get; protected set; } public bool IsInitialized { get; set; } + protected readonly ILogger ServerLogger; public int Port { get; private set; } protected string FSGame; diff --git a/SharedLibraryCore/Services/ChangeHistoryService.cs b/SharedLibraryCore/Services/ChangeHistoryService.cs index 7b3ceefb3..ad49608b0 100644 --- a/SharedLibraryCore/Services/ChangeHistoryService.cs +++ b/SharedLibraryCore/Services/ChangeHistoryService.cs @@ -5,11 +5,20 @@ using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace SharedLibraryCore.Services { public class ChangeHistoryService : IEntityService { + private readonly ILogger _logger; + + public ChangeHistoryService(ILogger logger) + { + _logger = logger; + } + public Task Create(EFChangeHistory entity) { throw new NotImplementedException(); @@ -79,8 +88,7 @@ namespace SharedLibraryCore.Services catch (Exception ex) { - e.Owner.Logger.WriteWarning(ex.Message); - e.Owner.Logger.WriteDebug(ex.GetExceptionInfo()); + _logger.LogError(ex, "Could not persist change @{change}", change); } finally diff --git a/SharedLibraryCore/Services/ClientService.cs b/SharedLibraryCore/Services/ClientService.cs index 094e09bd0..61deb4fec 100644 --- a/SharedLibraryCore/Services/ClientService.cs +++ b/SharedLibraryCore/Services/ClientService.cs @@ -8,22 +8,28 @@ using System; using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using Serilog.Context; using static SharedLibraryCore.Database.Models.EFClient; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace SharedLibraryCore.Services { public class ClientService : IEntityService, IResourceQueryHelper { private readonly IDatabaseContextFactory _contextFactory; + private readonly ILogger _logger; - public ClientService(IDatabaseContextFactory databaseContextFactory) + public ClientService(ILogger logger, IDatabaseContextFactory databaseContextFactory) { _contextFactory = databaseContextFactory; + _logger = logger; } public async Task Create(EFClient entity) { using (var context = new DatabaseContext()) + using (LogContext.PushProperty("Server", entity?.CurrentServer?.ToString())) { int? linkId = null; int? aliasId = null; @@ -40,13 +46,13 @@ namespace SharedLibraryCore.Services { linkId = existingAliases.OrderBy(_alias => _alias.LinkId).First().LinkId; - entity.CurrentServer.Logger.WriteDebug($"[create] client with new GUID {entity} has existing link {linkId}"); + _logger.LogDebug("[create] client with new GUID {entity} has existing link {linkId}", entity.ToString(), linkId); var existingExactAlias = existingAliases.FirstOrDefault(_alias => _alias.Name == entity.Name); if (existingExactAlias != null) { - entity.CurrentServer.Logger.WriteDebug($"[create] client with new GUID {entity} has existing alias {existingExactAlias.AliasId}"); + _logger.LogDebug("[create] client with new GUID {entity} has existing alias {aliasId}", entity.ToString(), existingExactAlias.AliasId); aliasId = existingExactAlias.AliasId; } } @@ -60,13 +66,13 @@ namespace SharedLibraryCore.Services NetworkId = entity.NetworkId }; - entity.CurrentServer.Logger.WriteDebug($"[create] adding {entity} to context"); + _logger.LogDebug("[create] adding {entity} to context", entity.ToString()); context.Clients.Add(client); // they're just using a new GUID if (aliasId.HasValue) { - entity.CurrentServer.Logger.WriteDebug($"[create] setting {entity}'s alias id and linkid to ({aliasId.Value}, {linkId.Value})"); + _logger.LogDebug("[create] setting {entity}'s alias id and linkid to ({aliasId}, {linkId})", entity.ToString(), aliasId, linkId); client.CurrentAliasId = aliasId.Value; client.AliasLinkId = linkId.Value; } @@ -74,7 +80,7 @@ namespace SharedLibraryCore.Services // link was found but they don't have an exact alias else if (!aliasId.HasValue && linkId.HasValue) { - entity.CurrentServer.Logger.WriteDebug($"[create] setting {entity}'s linkid to {linkId.Value}, but creating new alias"); + _logger.LogDebug("[create] setting {entity}'s linkid to {linkId}, but creating new alias", entity.ToString(), linkId); client.AliasLinkId = linkId.Value; client.CurrentAlias = new EFAlias() { @@ -89,7 +95,7 @@ namespace SharedLibraryCore.Services // brand new players (supposedly) else { - entity.CurrentServer.Logger.WriteDebug($"[create] creating new Link and Alias for {entity}"); + _logger.LogDebug("[create] creating new Link and Alias for {entity}", entity.ToString()); var link = new EFAliasLink(); var alias = new EFAlias() { @@ -114,129 +120,139 @@ namespace SharedLibraryCore.Services private async Task UpdateAlias(string originalName, int? ip, EFClient entity, DatabaseContext context) { - string name = originalName.CapClientName(EFAlias.MAX_NAME_LENGTH); - - // entity is the tracked db context item - // get all aliases by IP address and LinkId - var iqAliases = context.Aliases - .Include(a => a.Link) - // we only want alias that have the same IP address or share a link - .Where(_alias => _alias.IPAddress == ip || (_alias.LinkId == entity.AliasLinkId)); - - var aliases = await iqAliases.ToListAsync(); - var currentIPs = aliases.Where(_a2 => _a2.IPAddress != null).Select(_a2 => _a2.IPAddress).Distinct(); - var floatingIPAliases = await context.Aliases.Where(_alias => currentIPs.Contains(_alias.IPAddress)).ToListAsync(); - aliases.AddRange(floatingIPAliases); - - // see if they have a matching IP + Name but new NetworkId - var existingExactAlias = aliases.OrderBy(_alias => _alias.LinkId).FirstOrDefault(a => a.Name == name && a.IPAddress == ip); - bool hasExactAliasMatch = existingExactAlias != null; - - // if existing alias matches link them - var newAliasLink = existingExactAlias?.Link; - // if no exact matches find the first IP or LinkId that matches - newAliasLink = newAliasLink ?? aliases.OrderBy(_alias => _alias.LinkId).FirstOrDefault()?.Link; - // if no matches are found, use our current one ( it will become permanent ) - newAliasLink = newAliasLink ?? entity.AliasLink; - - bool hasExistingAlias = aliases.Count > 0; - bool isAliasLinkUpdated = newAliasLink.AliasLinkId != entity.AliasLink.AliasLinkId; - - await context.SaveChangesAsync(); - int distinctLinkCount = aliases.Select(_alias => _alias.LinkId).Distinct().Count(); - // this happens when the link we found is different than the one we create before adding an IP - if (isAliasLinkUpdated || distinctLinkCount > 1) + using (LogContext.PushProperty("Server", entity?.CurrentServer?.ToString())) { - entity.CurrentServer.Logger.WriteDebug($"[updatealias] found a link for {entity} so we are updating link from {entity.AliasLink.AliasLinkId} to {newAliasLink.AliasLinkId}"); + string name = originalName.CapClientName(EFAlias.MAX_NAME_LENGTH); - var completeAliasLinkIds = aliases.Select(_item => _item.LinkId) - .Append(entity.AliasLinkId) - .Distinct() - .ToList(); + // entity is the tracked db context item + // get all aliases by IP address and LinkId + var iqAliases = context.Aliases + .Include(a => a.Link) + // we only want alias that have the same IP address or share a link + .Where(_alias => _alias.IPAddress == ip || (_alias.LinkId == entity.AliasLinkId)); - entity.CurrentServer.Logger.WriteDebug($"[updatealias] updating aliasLinks {string.Join(',', completeAliasLinkIds)} for IP {ip} to {newAliasLink.AliasLinkId}"); + var aliases = await iqAliases.ToListAsync(); + var currentIPs = aliases.Where(_a2 => _a2.IPAddress != null).Select(_a2 => _a2.IPAddress).Distinct(); + var floatingIPAliases = await context.Aliases.Where(_alias => currentIPs.Contains(_alias.IPAddress)) + .ToListAsync(); + aliases.AddRange(floatingIPAliases); - // update all the clients that have the old alias link - await context.Clients - .Where(_client => completeAliasLinkIds.Contains(_client.AliasLinkId)) - .ForEachAsync(_client => _client.AliasLinkId = newAliasLink.AliasLinkId); + // see if they have a matching IP + Name but new NetworkId + var existingExactAlias = aliases.OrderBy(_alias => _alias.LinkId) + .FirstOrDefault(a => a.Name == name && a.IPAddress == ip); + bool hasExactAliasMatch = existingExactAlias != null; - // we also need to update all the penalties or they get deleted - // scenario - // link1 joins with ip1 - // link2 joins with ip2, - // link2 receives penalty - // link2 joins with ip1 - // pre existing link for link2 detected - // link2 is deleted - // link2 penalties are orphaned - await context.Penalties - .Where(_penalty => completeAliasLinkIds.Contains(_penalty.LinkId)) - .ForEachAsync(_penalty => _penalty.LinkId = newAliasLink.AliasLinkId); + // if existing alias matches link them + var newAliasLink = existingExactAlias?.Link; + // if no exact matches find the first IP or LinkId that matches + newAliasLink = newAliasLink ?? aliases.OrderBy(_alias => _alias.LinkId).FirstOrDefault()?.Link; + // if no matches are found, use our current one ( it will become permanent ) + newAliasLink = newAliasLink ?? entity.AliasLink; - entity.AliasLink = newAliasLink; - entity.AliasLinkId = newAliasLink.AliasLinkId; - - // update all previous aliases - await context.Aliases - .Where(_alias => completeAliasLinkIds.Contains(_alias.LinkId)) - .ForEachAsync(_alias => _alias.LinkId = newAliasLink.AliasLinkId); + bool hasExistingAlias = aliases.Count > 0; + bool isAliasLinkUpdated = newAliasLink.AliasLinkId != entity.AliasLink.AliasLinkId; await context.SaveChangesAsync(); - // we want to delete the now inactive alias - if (newAliasLink.AliasLinkId != entity.AliasLinkId) + int distinctLinkCount = aliases.Select(_alias => _alias.LinkId).Distinct().Count(); + // this happens when the link we found is different than the one we create before adding an IP + if (isAliasLinkUpdated || distinctLinkCount > 1) { - context.AliasLinks.Remove(entity.AliasLink); - await context.SaveChangesAsync(); - } - } + _logger.LogDebug( + "[updatealias] found a link for {entity} so we are updating link from {oldAliasLinkId} to {newAliasLinkId}", + entity.ToString(), entity.AliasLink.AliasLinkId, newAliasLink.AliasLinkId); - // the existing alias matches ip and name, so we can just ignore the temporary one - if (hasExactAliasMatch) - { - entity.CurrentServer.Logger.WriteDebug($"[updatealias] {entity} has exact alias match"); + var completeAliasLinkIds = aliases.Select(_item => _item.LinkId) + .Append(entity.AliasLinkId) + .Distinct() + .ToList(); - var oldAlias = entity.CurrentAlias; - entity.CurrentAliasId = existingExactAlias.AliasId; - entity.CurrentAlias = existingExactAlias; - await context.SaveChangesAsync(); + _logger.LogDebug("[updatealias] updating aliasLinks {links} for IP {ip} to {linkId}", + string.Join(',', completeAliasLinkIds), ip, newAliasLink.AliasLinkId); - // the alias is the same so we can just remove it - if (oldAlias.AliasId != existingExactAlias.AliasId && oldAlias.AliasId > 0) - { + // update all the clients that have the old alias link await context.Clients - .Where(_client => _client.CurrentAliasId == oldAlias.AliasId) - .ForEachAsync(_client => _client.CurrentAliasId = existingExactAlias.AliasId); + .Where(_client => completeAliasLinkIds.Contains(_client.AliasLinkId)) + .ForEachAsync(_client => _client.AliasLinkId = newAliasLink.AliasLinkId); + + // we also need to update all the penalties or they get deleted + // scenario + // link1 joins with ip1 + // link2 joins with ip2, + // link2 receives penalty + // link2 joins with ip1 + // pre existing link for link2 detected + // link2 is deleted + // link2 penalties are orphaned + await context.Penalties + .Where(_penalty => completeAliasLinkIds.Contains(_penalty.LinkId)) + .ForEachAsync(_penalty => _penalty.LinkId = newAliasLink.AliasLinkId); + + entity.AliasLink = newAliasLink; + entity.AliasLinkId = newAliasLink.AliasLinkId; + + // update all previous aliases + await context.Aliases + .Where(_alias => completeAliasLinkIds.Contains(_alias.LinkId)) + .ForEachAsync(_alias => _alias.LinkId = newAliasLink.AliasLinkId); await context.SaveChangesAsync(); - - if (context.Entry(oldAlias).State != EntityState.Deleted) + // we want to delete the now inactive alias + if (newAliasLink.AliasLinkId != entity.AliasLinkId) { - entity.CurrentServer.Logger.WriteDebug($"[updatealias] {entity} has exact alias match, so we're going to try to remove aliasId {oldAlias.AliasId} with linkId {oldAlias.AliasId}"); - context.Aliases.Remove(oldAlias); + context.AliasLinks.Remove(entity.AliasLink); await context.SaveChangesAsync(); } } - } - // theres no exact match, but they've played before with the GUID or IP - else - { - entity.CurrentServer.Logger.WriteDebug($"[updatealias] {entity} is using a new alias"); - - var newAlias = new EFAlias() + // the existing alias matches ip and name, so we can just ignore the temporary one + if (hasExactAliasMatch) { - DateAdded = DateTime.UtcNow, - IPAddress = ip, - LinkId = newAliasLink.AliasLinkId, - Name = name, - SearchableName = name.StripColors().ToLower(), - Active = true, - }; + _logger.LogDebug("[updatealias] {entity} has exact alias match", entity.ToString()); - entity.CurrentAlias = newAlias; - entity.CurrentAliasId = 0; - await context.SaveChangesAsync(); + var oldAlias = entity.CurrentAlias; + entity.CurrentAliasId = existingExactAlias.AliasId; + entity.CurrentAlias = existingExactAlias; + await context.SaveChangesAsync(); + + // the alias is the same so we can just remove it + if (oldAlias.AliasId != existingExactAlias.AliasId && oldAlias.AliasId > 0) + { + await context.Clients + .Where(_client => _client.CurrentAliasId == oldAlias.AliasId) + .ForEachAsync(_client => _client.CurrentAliasId = existingExactAlias.AliasId); + + await context.SaveChangesAsync(); + + if (context.Entry(oldAlias).State != EntityState.Deleted) + { + _logger.LogDebug( + "[updatealias] {entity} has exact alias match, so we're going to try to remove aliasId {aliasId} with linkId {linkId}", + entity.ToString(), oldAlias.AliasId, oldAlias.LinkId); + context.Aliases.Remove(oldAlias); + await context.SaveChangesAsync(); + } + } + } + + // theres no exact match, but they've played before with the GUID or IP + else + { + _logger.LogDebug("[updatealias] {entity} is using a new alias", entity.ToString()); + + var newAlias = new EFAlias() + { + DateAdded = DateTime.UtcNow, + IPAddress = ip, + LinkId = newAliasLink.AliasLinkId, + Name = name, + SearchableName = name.StripColors().ToLower(), + Active = true, + }; + + entity.CurrentAlias = newAlias; + entity.CurrentAliasId = 0; + await context.SaveChangesAsync(); + } } } @@ -261,29 +277,29 @@ namespace SharedLibraryCore.Services entity.Level = newPermission; await ctx.SaveChangesAsync(); -#if DEBUG == true - temporalClient.CurrentServer.Logger.WriteDebug($"Updated {temporalClient.ClientId} to {newPermission}"); -#endif - - var linkedPermissionSet = new[] { Permission.Banned, Permission.Flagged }; - // if their permission level has been changed to level that needs to be updated on all accounts - if (linkedPermissionSet.Contains(newPermission) || linkedPermissionSet.Contains(oldPermission)) + using (LogContext.PushProperty("Server", entity?.CurrentServer?.ToString())) { - //get all clients that have the same linkId - var iqMatchingClients = ctx.Clients - .Where(_client => _client.AliasLinkId == entity.AliasLinkId); + _logger.LogInformation("Updated {clientId} to {newPermission}", temporalClient.ClientId, newPermission); - // this updates the level for all the clients with the same LinkId - // only if their new level is flagged or banned - await iqMatchingClients.ForEachAsync(_client => + var linkedPermissionSet = new[] {Permission.Banned, Permission.Flagged}; + // if their permission level has been changed to level that needs to be updated on all accounts + if (linkedPermissionSet.Contains(newPermission) || linkedPermissionSet.Contains(oldPermission)) { - _client.Level = newPermission; -#if DEBUG == true - temporalClient.CurrentServer.Logger.WriteDebug($"Updated linked {_client.ClientId} to {newPermission}"); -#endif - }); + //get all clients that have the same linkId + var iqMatchingClients = ctx.Clients + .Where(_client => _client.AliasLinkId == entity.AliasLinkId); - await ctx.SaveChangesAsync(); + // this updates the level for all the clients with the same LinkId + // only if their new level is flagged or banned + await iqMatchingClients.ForEachAsync(_client => + { + _client.Level = newPermission; + _logger.LogInformation("Updated linked {clientId} to {newPermission}", _client.ClientId, + newPermission); + }); + + await ctx.SaveChangesAsync(); + } } } @@ -432,7 +448,7 @@ namespace SharedLibraryCore.Services { if (temporalClient.ClientId < 1) { - temporalClient.CurrentServer?.Logger.WriteDebug($"[update] {temporalClient} needs to be updated but they do not have a valid client id, ignoring.."); + _logger.LogDebug("[update] {client} needs to be updated but they do not have a valid client id, ignoring..", temporalClient.ToString()); // note: we never do anything with the result of this so we can safely return null return null; } diff --git a/SharedLibraryCore/SharedLibraryCore.csproj b/SharedLibraryCore/SharedLibraryCore.csproj index 901741fba..421860292 100644 --- a/SharedLibraryCore/SharedLibraryCore.csproj +++ b/SharedLibraryCore/SharedLibraryCore.csproj @@ -3,8 +3,6 @@ Library netcoreapp3.1 - - RaidMax.IW4MAdmin.SharedLibraryCore 2.4.10 RaidMax @@ -21,8 +19,9 @@ true MIT Shared Library for IW4MAdmin - 2.4.10.0 - 2.4.10.0 + 2020.11.11.1 + 2020.11.11.1 + 2020.11.11.1 @@ -54,6 +53,7 @@ + diff --git a/SharedLibraryCore/Utilities.cs b/SharedLibraryCore/Utilities.cs index 827589c18..de3640893 100644 --- a/SharedLibraryCore/Utilities.cs +++ b/SharedLibraryCore/Utilities.cs @@ -17,14 +17,18 @@ using System.Text; using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.Database.Models.EFClient; using static SharedLibraryCore.Database.Models.EFPenalty; using static SharedLibraryCore.Server; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace SharedLibraryCore { public static class Utilities { + // note: this is only to be used by classes not created by dependency injection + public static ILogger DefaultLogger { get; set; } #if DEBUG == true public static string OperatingDirectory => $"{Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location)}{Path.DirectorySeparatorChar}"; #else @@ -881,8 +885,7 @@ namespace SharedLibraryCore catch (Exception e) { - logger.WriteWarning($"Could not create penalty of type {penalty.Type.ToString()}"); - logger.WriteDebug(e.GetExceptionInfo()); + logger.LogError(e, $"Could not create penalty of type {penalty.Type.ToString()}"); } return false; diff --git a/Tests/ApplicationTests/BaseEventParserTests.cs b/Tests/ApplicationTests/BaseEventParserTests.cs index 37f8f06e9..242878f95 100644 --- a/Tests/ApplicationTests/BaseEventParserTests.cs +++ b/Tests/ApplicationTests/BaseEventParserTests.cs @@ -9,6 +9,7 @@ using SharedLibraryCore; using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; using System; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.GameEvent; namespace ApplicationTests @@ -18,7 +19,6 @@ namespace ApplicationTests { private EventLogTest eventLogData; private IServiceProvider serviceProvider; - private ILogger fakeLogger; private ApplicationConfiguration appConfig; [SetUp] @@ -27,13 +27,12 @@ namespace ApplicationTests eventLogData = JsonConvert.DeserializeObject(System.IO.File.ReadAllText("Files/GameEvents.json")); appConfig = ConfigurationGenerators.CreateApplicationConfiguration(); - fakeLogger = A.Fake(); serviceProvider = new ServiceCollection() + .AddSingleton(A.Fake()) .AddSingleton() .AddTransient() .AddSingleton() .AddSingleton(appConfig) - .AddSingleton(fakeLogger) .BuildServiceProvider(); } @@ -86,18 +85,6 @@ namespace ApplicationTests }); } - [Test] - public void TestCustomEventParsingLogsWarningOnException() - { - var eventParser = serviceProvider.GetService(); - - eventParser.RegisterCustomEvent("test", "test", (a, b, c) => throw new Exception()); - eventParser.GenerateGameEvent("12:12 test"); - - A.CallTo(() => fakeLogger.WriteWarning(A.Ignored)) - .MustHaveHappenedOnceExactly(); - } - [Test] public void Test_CustomCommandPrefix_Parses() { diff --git a/Tests/ApplicationTests/BaseRConParserTests.cs b/Tests/ApplicationTests/BaseRConParserTests.cs index 781fe1c11..dc4068e30 100644 --- a/Tests/ApplicationTests/BaseRConParserTests.cs +++ b/Tests/ApplicationTests/BaseRConParserTests.cs @@ -1,5 +1,6 @@ using FakeItEasy; using IW4MAdmin.Application.RconParsers; +using Microsoft.Extensions.Logging; using NUnit.Framework; using SharedLibraryCore.Interfaces; @@ -8,10 +9,12 @@ namespace ApplicationTests [TestFixture] public class BaseRConParserTests { + private readonly ILogger _fakeLogger = A.Fake>(); + [Test] public void SetDvarAsync_FormatStringType() { - var parser = new BaseRConParser(A.Fake()); + var parser = new BaseRConParser(_fakeLogger, A.Fake()); var connection = A.Fake(); parser.SetDvarAsync(connection, "test", "test").Wait(); @@ -23,7 +26,7 @@ namespace ApplicationTests [Test] public void SetDvarAsync_FormatEmptyStringTypeIncludesQuotes() { - var parser = new BaseRConParser(A.Fake()); + var parser = new BaseRConParser(_fakeLogger, A.Fake()); var connection = A.Fake(); parser.SetDvarAsync(connection, "test", "").Wait(); @@ -35,7 +38,7 @@ namespace ApplicationTests [Test] public void SetDvarAsync_FormatsNonString() { - var parser = new BaseRConParser(A.Fake()); + var parser = new BaseRConParser(_fakeLogger, A.Fake()); var connection = A.Fake(); parser.SetDvarAsync(connection, "test", 123).Wait(); diff --git a/Tests/ApplicationTests/CommandTests.cs b/Tests/ApplicationTests/CommandTests.cs index fc73a2cc2..aa6ff8c21 100644 --- a/Tests/ApplicationTests/CommandTests.cs +++ b/Tests/ApplicationTests/CommandTests.cs @@ -22,7 +22,6 @@ namespace ApplicationTests [TestFixture] public class CommandTests { - ILogger logger; private IServiceProvider serviceProvider; private ITranslationLookup transLookup; private CommandConfiguration cmdConfig; @@ -34,8 +33,6 @@ namespace ApplicationTests [SetUp] public void Setup() { - logger = A.Fake(); - serviceProvider = new ServiceCollection() .BuildBase(new EventHandlerMock(true)) .AddSingleton(A.Fake()) diff --git a/Tests/ApplicationTests/DependencyInjectionExtensions.cs b/Tests/ApplicationTests/DependencyInjectionExtensions.cs index 954c7a4c3..61352967c 100644 --- a/Tests/ApplicationTests/DependencyInjectionExtensions.cs +++ b/Tests/ApplicationTests/DependencyInjectionExtensions.cs @@ -4,10 +4,10 @@ using FakeItEasy; using IW4MAdmin; using Microsoft.Extensions.DependencyInjection; using SharedLibraryCore.Configuration; -using SharedLibraryCore.Database; using SharedLibraryCore.Interfaces; -using SharedLibraryCore.Services; using System; +using Microsoft.Extensions.Logging; +using SharedLibraryCore; namespace ApplicationTests { @@ -34,10 +34,9 @@ namespace ApplicationTests A.CallTo(() => transLookup[A.Ignored]) .Returns("test"); - A.CallTo(() => manager.GetLogger(A.Ignored)) - .Returns(logger); - - serviceCollection.AddSingleton(logger) + serviceCollection + .AddLogging() + .AddSingleton(A.Fake()) .AddSingleton(manager) .AddSingleton() .AddSingleton(A.Fake()) @@ -53,8 +52,13 @@ namespace ApplicationTests .AddSingleton(ConfigurationGenerators.CreateCommandConfiguration()) .AddSingleton, ApplicationConfigurationHandlerMock>(); - serviceCollection.AddSingleton(_sp => new IW4MServer(_sp.GetRequiredService(), ConfigurationGenerators.CreateServerConfiguration(), - _sp.GetRequiredService(), _sp.GetRequiredService(), _sp.GetRequiredService(), _sp.GetRequiredService()) + serviceCollection.AddSingleton(_sp => new IW4MServer(_sp.GetRequiredService(), + ConfigurationGenerators.CreateServerConfiguration(), + _sp.GetRequiredService(), + _sp.GetRequiredService(), + _sp.GetRequiredService(), + _sp.GetRequiredService(), + _sp.GetRequiredService>()) { RconParser = _sp.GetRequiredService() }); diff --git a/Tests/ApplicationTests/IW4MServerTests.cs b/Tests/ApplicationTests/IW4MServerTests.cs index 02d645b6b..99c269a5c 100644 --- a/Tests/ApplicationTests/IW4MServerTests.cs +++ b/Tests/ApplicationTests/IW4MServerTests.cs @@ -11,6 +11,7 @@ using SharedLibraryCore.Database.Models; using System.Threading.Tasks; using ApplicationTests.Mocks; using System.Linq; +using Microsoft.Extensions.Logging; using SharedLibraryCore; using SharedLibraryCore.Exceptions; using SharedLibraryCore.Configuration; @@ -529,9 +530,6 @@ namespace ApplicationTests { await server.ProcessUpdatesAsync(new System.Threading.CancellationToken()); } - - A.CallTo(() => fakeLogger.WriteError(A.Ignored)) - .MustNotHaveHappened(); } [Test] @@ -555,9 +553,6 @@ namespace ApplicationTests await server.ExecuteEvent(e); } - A.CallTo(() => fakeLogger.WriteError(A.Ignored)) - .MustHaveHappenedOnceExactly(); - Assert.IsNotEmpty(mockEventHandler.Events.Where(_event => _event.Type == GameEvent.EventType.ConnectionLost)); Assert.AreEqual("err", (mockEventHandler.Events[0].Extra as NetworkException).Message); } diff --git a/Tests/ApplicationTests/PluginTests.cs b/Tests/ApplicationTests/PluginTests.cs index 893c8e221..475501bc4 100644 --- a/Tests/ApplicationTests/PluginTests.cs +++ b/Tests/ApplicationTests/PluginTests.cs @@ -11,11 +11,9 @@ using SharedLibraryCore.Database.Models; using SharedLibraryCore.Interfaces; using SharedLibraryCore.Services; using System; -using System.Collections.Generic; using System.IO; -using System.Linq; -using System.Text; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; namespace ApplicationTests { @@ -53,7 +51,7 @@ namespace ApplicationTests [Test] public async Task Test_GenericGuidClientIsKicked() { - var plugin = new ScriptPlugin(Path.Join(PLUGIN_DIR, "SharedGUIDKick.js"), PLUGIN_DIR); + var plugin = new ScriptPlugin(serviceProvider.GetRequiredService(), Path.Join(PLUGIN_DIR, "SharedGUIDKick.js"), PLUGIN_DIR); var server = serviceProvider.GetRequiredService(); server.GameName = Server.Game.IW4; var client = ClientGenerators.CreateBasicClient(server, hasIp: false, clientState: EFClient.ClientState.Connecting); diff --git a/Tests/ApplicationTests/ServerTests.cs b/Tests/ApplicationTests/ServerTests.cs index df792d8bb..1cffc1f09 100644 --- a/Tests/ApplicationTests/ServerTests.cs +++ b/Tests/ApplicationTests/ServerTests.cs @@ -7,25 +7,19 @@ using SharedLibraryCore.Configuration; using SharedLibraryCore.Interfaces; using System; using System.Diagnostics; +using Microsoft.Extensions.Logging; +using SharedLibraryCore; namespace ApplicationTests { [TestFixture] public class ServerTests { - ILogger logger; [SetUp] public void Setup() { - logger = A.Fake(); - void testLog(string msg) => Console.WriteLine(msg); - - A.CallTo(() => logger.WriteError(A.Ignored)).Invokes((string msg) => testLog(msg)); - A.CallTo(() => logger.WriteWarning(A.Ignored)).Invokes((string msg) => testLog(msg)); - A.CallTo(() => logger.WriteInfo(A.Ignored)).Invokes((string msg) => testLog(msg)); - A.CallTo(() => logger.WriteDebug(A.Ignored)).Invokes((string msg) => testLog(msg)); } [Test] @@ -34,7 +28,8 @@ namespace ApplicationTests var mgr = A.Fake(); var server = new IW4MServer(mgr, new SharedLibraryCore.Configuration.ServerConfiguration() { IPAddress = "127.0.0.1", Port = 28960 }, - A.Fake(), A.Fake(), A.Fake(), A.Fake()); + A.Fake(), A.Fake(), + A.Fake(), A.Fake(), A.Fake>()); var parser = new BaseEventParser(A.Fake(), A.Fake(), A.Fake()); parser.Configuration.GuidNumberStyle = System.Globalization.NumberStyles.Integer; @@ -56,11 +51,11 @@ namespace ApplicationTests public void LogFileReplay() { var mgr = A.Fake(); - A.CallTo(() => mgr.GetLogger(A.Ignored)).Returns(logger); var server = new IW4MServer(mgr, new SharedLibraryCore.Configuration.ServerConfiguration() { IPAddress = "127.0.0.1", Port = 28960 }, - A.Fake(), A.Fake(), A.Fake(), A.Fake()); + A.Fake(), A.Fake(), A.Fake(), A.Fake(), + A.Fake>()); var parser = new BaseEventParser(A.Fake(), A.Fake(), A.Fake()); parser.Configuration.GuidNumberStyle = System.Globalization.NumberStyles.Integer; @@ -70,7 +65,6 @@ namespace ApplicationTests foreach (string line in log) { var e = parser.GenerateGameEvent(line); - server.Logger.WriteInfo($"{e.GameTime}"); if (e.Origin != null) { e.Origin.CurrentServer = server; diff --git a/Tests/ApplicationTests/StatsTests.cs b/Tests/ApplicationTests/StatsTests.cs index e8fa46b31..9f647dc86 100644 --- a/Tests/ApplicationTests/StatsTests.cs +++ b/Tests/ApplicationTests/StatsTests.cs @@ -6,7 +6,6 @@ using FakeItEasy; using IW4MAdmin.Application.EventParsers; using System.Linq; using IW4MAdmin.Plugins.Stats.Models; -using IW4MAdmin.Application.Helpers; using IW4MAdmin.Plugins.Stats.Config; using System.Collections.Generic; using SharedLibraryCore.Database.Models; @@ -14,9 +13,12 @@ using Microsoft.Extensions.DependencyInjection; using IW4MAdmin.Plugins.Stats.Helpers; using ApplicationTests.Fixtures; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using SharedLibraryCore; using Stats.Helpers; using Stats.Dtos; using SharedLibraryCore.Configuration; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace ApplicationTests { @@ -41,13 +43,6 @@ namespace ApplicationTests .BuildServiceProvider(); contextFactory = serviceProvider.GetRequiredService(); - - void testLog(string msg) => Console.WriteLine(msg); - - A.CallTo(() => logger.WriteError(A.Ignored)).Invokes((string msg) => testLog(msg)); - A.CallTo(() => logger.WriteWarning(A.Ignored)).Invokes((string msg) => testLog(msg)); - A.CallTo(() => logger.WriteInfo(A.Ignored)).Invokes((string msg) => testLog(msg)); - A.CallTo(() => logger.WriteDebug(A.Ignored)).Invokes((string msg) => testLog(msg)); } [Test] @@ -66,13 +61,11 @@ namespace ApplicationTests A.CallTo(() => handlerFactory.GetConfigurationHandler(A.Ignored)) .Returns(config); - A.CallTo(() => mgr.GetLogger(A.Ignored)) - .Returns(logger); - var server = new IW4MServer(mgr, new SharedLibraryCore.Configuration.ServerConfiguration() { IPAddress = "127.0.0.1", Port = 28960 }, A.Fake(), - A.Fake(), A.Fake(), A.Fake()); + A.Fake(), + A.Fake(), A.Fake(), A.Fake>()); var parser = new BaseEventParser(A.Fake(), A.Fake(), A.Fake()); parser.Configuration.GuidNumberStyle = System.Globalization.NumberStyles.Integer; diff --git a/WebfrontCore/Controllers/API/ClientController.cs b/WebfrontCore/Controllers/API/ClientController.cs index 51fe34854..9f149635f 100644 --- a/WebfrontCore/Controllers/API/ClientController.cs +++ b/WebfrontCore/Controllers/API/ClientController.cs @@ -1,12 +1,13 @@ using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Mvc; -using SharedLibraryCore; using SharedLibraryCore.Dtos; using SharedLibraryCore.Interfaces; using System; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using WebfrontCore.Controllers.API.Dtos; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace WebfrontCore.Controllers.API { @@ -20,7 +21,7 @@ namespace WebfrontCore.Controllers.API private readonly IResourceQueryHelper _clientQueryHelper; private readonly ILogger _logger; - public ClientController(ILogger logger, IResourceQueryHelper clientQueryHelper) + public ClientController(ILogger logger, IResourceQueryHelper clientQueryHelper) { _logger = logger; _clientQueryHelper = clientQueryHelper; @@ -53,8 +54,7 @@ namespace WebfrontCore.Controllers.API catch (Exception e) { - _logger.WriteWarning($"Failed to retrieve clients with query - {request.ToDebugString()}"); - _logger.WriteDebug(e.GetExceptionInfo()); + _logger.LogWarning(e, "Failed to retrieve clients with query - {@request}", request); return StatusCode(StatusCodes.Status500InternalServerError, new ErrorResponse() { diff --git a/WebfrontCore/Controllers/ClientController.cs b/WebfrontCore/Controllers/ClientController.cs index 7b3d75c20..a7e792615 100644 --- a/WebfrontCore/Controllers/ClientController.cs +++ b/WebfrontCore/Controllers/ClientController.cs @@ -171,7 +171,7 @@ namespace WebfrontCore.Controllers var meta = await ProfileMetaListViewComponent.GetClientMeta(_metaService, metaFilterType, Client.Level, request); - if (meta.Count() == 0) + if (!meta.Any()) { return Ok(); } diff --git a/WebfrontCore/Controllers/HomeController.cs b/WebfrontCore/Controllers/HomeController.cs index 77aa71ecb..fbc03f6d4 100644 --- a/WebfrontCore/Controllers/HomeController.cs +++ b/WebfrontCore/Controllers/HomeController.cs @@ -3,19 +3,22 @@ using Microsoft.AspNetCore.Mvc; using SharedLibraryCore; using SharedLibraryCore.Dtos; using SharedLibraryCore.Interfaces; -using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using static SharedLibraryCore.Server; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace WebfrontCore.Controllers { public class HomeController : BaseController { private readonly ITranslationLookup _translationLookup; + private readonly ILogger _logger; - public HomeController(IManager manager, ITranslationLookup translationLookup) : base(manager) + public HomeController(ILogger logger, IManager manager, ITranslationLookup translationLookup) : base(manager) { + _logger = logger; _translationLookup = translationLookup; } @@ -43,10 +46,7 @@ namespace WebfrontCore.Controllers public IActionResult Error() { var exceptionFeature = HttpContext.Features.Get(); - Manager.GetLogger(0).WriteError($"[Webfront] {exceptionFeature.Error.Message}"); - Manager.GetLogger(0).WriteDebug(exceptionFeature.Path); - Manager.GetLogger(0).WriteDebug(exceptionFeature.Error.StackTrace); - + _logger.LogError("[Webfront] {path} {message} {@exception}", exceptionFeature.Path, exceptionFeature.Error.Message, exceptionFeature.Error); ViewBag.Description = Localization["WEBFRONT_ERROR_DESC"]; ViewBag.Title = Localization["WEBFRONT_ERROR_TITLE"]; return View(exceptionFeature.Error); diff --git a/WebfrontCore/Middleware/IPWhitelist.cs b/WebfrontCore/Middleware/IPWhitelist.cs index 85d8c1634..e6cebe32c 100644 --- a/WebfrontCore/Middleware/IPWhitelist.cs +++ b/WebfrontCore/Middleware/IPWhitelist.cs @@ -1,9 +1,8 @@ using Microsoft.AspNetCore.Http; -using SharedLibraryCore.Interfaces; -using System; -using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; +using ILogger = Microsoft.Extensions.Logging.ILogger; namespace WebfrontCore.Middleware { @@ -22,7 +21,7 @@ namespace WebfrontCore.Middleware /// /// /// list of textual ip addresses - public IPWhitelist(RequestDelegate nextRequest, ILogger logger, string[] whitelistedIps) + public IPWhitelist(RequestDelegate nextRequest, ILogger logger, string[] whitelistedIps) { _whitelistedIps = whitelistedIps.Select(_ip => System.Net.IPAddress.Parse(_ip).GetAddressBytes()).ToArray(); _nextRequest = nextRequest; @@ -31,21 +30,21 @@ namespace WebfrontCore.Middleware public async Task Invoke(HttpContext context) { - bool isAlllowed = true; + var isAllowed = true; if (_whitelistedIps.Length > 0) { - isAlllowed = _whitelistedIps.Any(_ip => _ip.SequenceEqual(context.Connection.RemoteIpAddress.GetAddressBytes())); + isAllowed = _whitelistedIps.Any(_ip => _ip.SequenceEqual(context.Connection.RemoteIpAddress.GetAddressBytes())); } - if (isAlllowed) + if (isAllowed) { await _nextRequest.Invoke(context); } else { - _logger.WriteInfo($"Blocking HTTP request from {context.Connection.RemoteIpAddress.ToString()}"); + _logger.LogDebug("Blocking HTTP request from {ipAddress}", context.Connection.RemoteIpAddress); context.Abort(); } } diff --git a/WebfrontCore/Startup.cs b/WebfrontCore/Startup.cs index 6db504e26..9d640d81b 100644 --- a/WebfrontCore/Startup.cs +++ b/WebfrontCore/Startup.cs @@ -79,11 +79,11 @@ namespace WebfrontCore }); #if DEBUG - mvcBuilder = mvcBuilder.AddRazorRuntimeCompilation(); + /*mvcBuilder = mvcBuilder.AddRazorRuntimeCompilation(); services.Configure(_options => { _options.ViewLocationFormats.Add(@"/Views/Plugins/{1}/{0}" + RazorViewEngine.ViewExtension); - }); + });*/ #endif foreach (var asm in pluginAssemblies()) @@ -103,13 +103,6 @@ namespace WebfrontCore options.LoginPath = "/"; }); -#if DEBUG - services.AddLogging(_builder => - { - _builder.AddDebug(); - }); -#endif - services.AddSingleton(Program.Manager); services.AddSingleton, ChatResourceQueryHelper>(); services.AddTransient, FindClientRequestValidator>(); @@ -121,7 +114,6 @@ namespace WebfrontCore services.AddSingleton(Program.ApplicationServiceProvider.GetService()); services.AddSingleton(Program.ApplicationServiceProvider.GetService()); services.AddSingleton(Program.ApplicationServiceProvider.GetService()); - services.AddSingleton(Program.ApplicationServiceProvider.GetService()); services.AddSingleton(Program.ApplicationServiceProvider.GetService>()); services.AddSingleton(Program.ApplicationServiceProvider.GetService()); services.AddSingleton(Program.ApplicationServiceProvider.GetService()); @@ -152,7 +144,7 @@ namespace WebfrontCore if (Program.Manager.GetApplicationSettings().Configuration().EnableWebfrontConnectionWhitelist) { - app.UseMiddleware(manager.GetLogger(0), manager.GetApplicationSettings().Configuration().WebfrontConnectionWhitelist); + app.UseMiddleware(Program.ApplicationServiceProvider.GetService>(), manager.GetApplicationSettings().Configuration().WebfrontConnectionWhitelist); } app.UseStaticFiles(); diff --git a/WebfrontCore/Views/Client/Find/Index.cshtml b/WebfrontCore/Views/Client/Find/Index.cshtml index 45387ec54..81d951620 100644 --- a/WebfrontCore/Views/Client/Find/Index.cshtml +++ b/WebfrontCore/Views/Client/Find/Index.cshtml @@ -1,4 +1,4 @@ -@model List +@model IList @{ var loc = SharedLibraryCore.Utilities.CurrentLocalization.LocalizationIndex; } diff --git a/WebfrontCore/Views/Shared/Components/PenaltyList/_List.cshtml b/WebfrontCore/Views/Shared/Components/PenaltyList/_List.cshtml index 63f6c2ac6..ed1dde7d5 100644 --- a/WebfrontCore/Views/Shared/Components/PenaltyList/_List.cshtml +++ b/WebfrontCore/Views/Shared/Components/PenaltyList/_List.cshtml @@ -1,7 +1,7 @@ @{ Layout = null; } -@model List +@model IList @{ foreach (var penalty in Model) diff --git a/WebfrontCore/Views/Shared/ResponseStatusCode.cshtml b/WebfrontCore/Views/Shared/ResponseStatusCode.cshtml index 384a43601..0a79e1641 100644 --- a/WebfrontCore/Views/Shared/ResponseStatusCode.cshtml +++ b/WebfrontCore/Views/Shared/ResponseStatusCode.cshtml @@ -1,4 +1,4 @@ -@model int +@model int? @{ ViewData["Title"] = "Error"; } @@ -6,7 +6,7 @@

@SharedLibraryCore.Utilities.CurrentLocalization.LocalizationIndex["WEBFRONT_ERROR_GENERIC_TITLE"]

@SharedLibraryCore.Utilities.CurrentLocalization.LocalizationIndex["WEBFRONT_ERROR_GENERIC_DESC"]

- @if (Model == 404) + @if (Model.HasValue && Model.Value == 404) { @SharedLibraryCore.Utilities.CurrentLocalization.LocalizationIndex["WEBFRONT_ERROR_NOTFOUND"] } diff --git a/WebfrontCore/WebfrontCore.csproj b/WebfrontCore/WebfrontCore.csproj index b3e416e1f..db0af4d22 100644 --- a/WebfrontCore/WebfrontCore.csproj +++ b/WebfrontCore/WebfrontCore.csproj @@ -81,7 +81,13 @@ - + + + + + + +