improve server logging (use nlog)

cgytrus · Nov 22, 2021 · 7b9e579 · 7b9e579
1 parent d42a590
commit 7b9e579
Show file tree

Hide file tree

Showing 7 changed files with 132 additions and 101 deletions.
diff --git a/.editorconfig b/.editorconfig
@@ -67,7 +67,6 @@ dotnet_style_qualification_for_field=false:suggestion
 dotnet_style_qualification_for_method=false:suggestion
 dotnet_style_qualification_for_property=false:suggestion
 dotnet_style_require_accessibility_modifiers=for_non_interface_members:warning
-dotnet_diagnostic.CA1716.severity = none
 
 # ReSharper properties
 resharper_align_linq_query=true
@@ -153,3 +152,6 @@ resharper_use_deconstruction_highlighting=warning
 resharper_web_config_module_not_resolved_highlighting=warning
 resharper_web_config_type_not_resolved_highlighting=warning
 resharper_web_config_wrong_module_highlighting=warning
+
+[*.csproj]
+indent_size=2
diff --git a/CatsAreOnlineServer/CatsAreOnlineServer.csproj b/CatsAreOnlineServer/CatsAreOnlineServer.csproj
@@ -9,8 +9,14 @@
           <NoWarn>NU1701</NoWarn>
       </PackageReference>
     <PackageReference Include="NBrigadier" Version="1.0.17.5" />
+    <PackageReference Include="NLog" Version="4.7.12" />
   </ItemGroup>
   <ItemGroup>
     <ProjectReference Include="..\CatsAreOnline.Shared\CatsAreOnline.Shared.csproj" />
   </ItemGroup>
+  <ItemGroup>
+    <None Update="NLog.config">
+      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
+    </None>
+  </ItemGroup>
 </Project>
diff --git a/CatsAreOnlineServer/NLog.config b/CatsAreOnlineServer/NLog.config
@@ -0,0 +1,57 @@
+<?xml version="1.0" encoding="utf-8" ?>
+<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
+      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+      throwConfigExceptions="true">
+    <time xsi:type="FastUTC" />
+
+    <variable name="dateFormat" value="dd.MM.yyyy-hh.mm.ss" />
+    <variable name="startTime" value="${cached:cached=true:inner=${date:format=${dateFormat}}}" />
+
+    <variable name="serverName" value="SERVER" />
+    <variable name="playerLogger"
+              value="${logger:whenEmpty=${serverName}}" />
+    <variable name="chatTo"
+              value="${when:when='${event-properties:whisper}' == true:inner= to ${event-properties:to:whenEmpty=${serverName}}}" />
+
+    <variable name="defaultLayout" value="(${longdate}) ${level:uppercase=true} in ${logger}\: ${message}" />
+    <variable name="playerActionLayout" value="(${longdate}) ACTION by ${playerLogger}\: ${message}" />
+    <variable name="chatLayout" value="(${longdate}) [${playerLogger}${chatTo}] ${message}" />
+
+    <variable name="layoutName" value="${event-properties:layout}" />
+
+    <!--ugliest shit i've ever written-->
+    <variable name="autoLayout1"
+              value="${when:when='${layoutName}' == 'chat':inner=${chatLayout}:else=${defaultLayout}}" />
+    <variable name="autoLayout0"
+              value="${when:when='${layoutName}' == 'playerAction':inner=${playerActionLayout}:else=${autoLayout1}}" />
+    <variable name="autoLayout"
+              value="${autoLayout0}" />
+
+    <targets>
+        <target name="debugger" xsi:type="Debugger" layout="${autoLayout}" />
+        <target name="console" xsi:type="ColoredConsole" layout="${autoLayout}" useDefaultRowHighlightingRules="false">
+            <highlight-row condition="'${event-properties:layout}' == 'playerAction'" foregroundColor="Cyan" />
+            <highlight-row condition="'${event-properties:success}' == true" foregroundColor="Green" />
+            <highlight-row condition="'${event-properties:progress}' == true" foregroundColor="DarkGreen" />
+            <highlight-row condition="'${event-properties:progressStart}' == true" foregroundColor="DarkGray" />
+            <highlight-row condition="'${event-properties:unhandled}' == true" foregroundColor="DarkGray" />
+            <highlight-row condition="level == LogLevel.Fatal" foregroundColor="DarkRed" />
+            <highlight-row condition="level == LogLevel.Error" foregroundColor="Red" />
+            <highlight-row condition="level == LogLevel.Warn" foregroundColor="Yellow" />
+            <highlight-row condition="level == LogLevel.Info" foregroundColor="White" />
+            <highlight-row condition="level == LogLevel.Debug" foregroundColor="DarkGray" />
+            <highlight-row condition="level == LogLevel.Trace" foregroundColor="DarkGray" />
+        </target>
+        <target name="file" xsi:type="File" fileName="${currentdir}\logs\latest.log"
+                header="This CaO Server (v${assembly-version}) log has started at ${startTime} on ${machinename}"
+                layout="${autoLayout}" maxArchiveFiles="10" archiveNumbering="DateAndSequence"
+                archiveDateFormat="${dateFormat}" archiveFileName="${currentdir}\logs\{#}.log" archiveEvery="None"
+                archiveOldFileOnStartup="true" />
+    </targets>
+
+    <rules>
+        <logger name="*" minlevel="Trace" writeTo="debugger" />
+        <logger name="*" minlevel="Trace" writeTo="console" />
+        <logger name="*" minlevel="Info" writeTo="file" />
+    </rules>
+</nlog>
diff --git a/CatsAreOnlineServer/src/MessageHandlers/DataMessageHandler.cs b/CatsAreOnlineServer/src/MessageHandlers/DataMessageHandler.cs
@@ -8,9 +8,13 @@
 
 using Lidgren.Network;
 
+using NLog;
+
 namespace CatsAreOnlineServer.MessageHandlers;
 
 public class DataMessageHandler {
+    private static readonly Logger logger = LogManager.GetCurrentClassLogger();
+
     public NetServer server { private get; init; }
     public Dictionary<NetConnection, Player> playerRegistry { private get; init; }
     public Dictionary<Guid, SyncedObject> syncedObjectRegistry { private get; init; }
@@ -35,11 +39,7 @@ public void MessageReceived(NetIncomingMessage message) {
         DataType type = (DataType)message.ReadByte();
 
         if(_messages.TryGetValue(type, out Action<NetIncomingMessage> action)) action(message);
-        else {
-            Console.ForegroundColor = ConsoleColor.Yellow;
-            Console.WriteLine($"[WARN] Unknown message type received ({type.ToString()})");
-            Console.ResetColor();
-        }
+        else logger.Warn($"Unknown message type received ({type.ToString()})");
     }
 
     private void PlayerChangedWorldPackReceived(NetIncomingMessage message) {
@@ -201,24 +201,15 @@ private void ChatMessageReceived(NetIncomingMessage message) {
 
         string text = message.ReadString();
 
-        Console.WriteLine($"[{player.username}] {text}");
-
-        NetOutgoingMessage resendMessage = server.CreateMessage();
-        resendMessage.Write((byte)DataType.ChatMessage);
-        resendMessage.Write(player.username);
-        resendMessage.Write(text);
-        server.SendMessage(resendMessage, playerRegistry.Select(ply => ply.Value.connection).ToList(),
-            DeliveryMethods.Reliable, 0);
+        Server.SendChatMessageToAll(player, text);
     }
 
     private static void CommandReceived(NetIncomingMessage message) {
         Player player = Server.GetPlayer(message);
         if(player is null) return;
 
         string command = message.ReadString();
-        Console.ForegroundColor = ConsoleColor.Cyan;
-        Console.WriteLine($"Received a command from {player.username} : '{command}'");
-        Console.ResetColor();
+        Server.LogPlayerAction(player, $"Command received: '{command}'");
         Server.ExecuteCommand(player, command);
     }
 

diff --git a/CatsAreOnlineServer/src/MessageHandlers/MessageHandler.cs b/CatsAreOnlineServer/src/MessageHandlers/MessageHandler.cs
@@ -6,9 +6,15 @@
 
 using Lidgren.Network;
 
+using NLog;
+
 namespace CatsAreOnlineServer.MessageHandlers;
 
 public class MessageHandler {
+    private static readonly Logger logger = LogManager.GetCurrentClassLogger();
+    private static readonly Logger progressLogger = logger.WithProperty("progress", true);
+    private static readonly Logger unhandledLogger = logger.WithProperty("unhandled", true);
+
     public NetServer server { private get; init; }
     public Dictionary<NetConnection, Player> playerRegistry { private get; init; }
     public Dictionary<Guid, SyncedObject> syncedObjectRegistry { private get; init; }
@@ -31,11 +37,7 @@ public class MessageHandler {
 
     public void MessageReceived(NetIncomingMessage message) {
         if(_messages.TryGetValue(message.MessageType, out Action<NetIncomingMessage> action)) action(message);
-        else {
-            Console.ForegroundColor = ConsoleColor.DarkGray;
-            Console.WriteLine($"[UNHANDLED] {message.MessageType.ToString()}");
-            Console.ResetColor();
-        }
+        else unhandledLogger.Info($"[UNHANDLED] {message.MessageType.ToString()}");
     }
 
     private void ConnectionApprovalReceived(NetIncomingMessage message) {
@@ -44,16 +46,12 @@ private void ConnectionApprovalReceived(NetIncomingMessage message) {
         string username = message.ReadString();
         string displayName = message.ReadString();
 
-        Console.ForegroundColor = ConsoleColor.DarkGreen;
-        Console.WriteLine($"Registering player {username} @ {ip}");
-        Console.ResetColor();
+        progressLogger.Info($"Registering player {username} @ {ip}");
 
         string error = Server.ValidateRegisteringPlayer(username, displayName, protocol);
         if(error is not null) {
             message.SenderConnection.Deny(error);
-            Console.ForegroundColor = ConsoleColor.Red;
-            Console.WriteLine($"Could not register player {username} @ {ip} ({error})");
-            Console.ResetColor();
+            logger.Error($"Could not register player {username} @ {ip} ({error})");
             return;
         }
 
@@ -96,27 +94,11 @@ private void ConnectionLatencyUpdatedReceived(NetIncomingMessage message) {
         }
     }
 
-    private static void VerboseDebugMessageReceived(NetBuffer message) {
-        Console.ForegroundColor = ConsoleColor.DarkGray;
-        Console.WriteLine($"[VERBOSE DEBUG] {message.ReadString()}");
-        Console.ResetColor();
-    }
+    private static void VerboseDebugMessageReceived(NetBuffer message) => logger.Trace(message.ReadString());
 
-    private static void DebugMessageReceived(NetBuffer message) {
-        Console.ForegroundColor = ConsoleColor.DarkGray;
-        Console.WriteLine($"[DEBUG] {message.ReadString()}");
-        Console.ResetColor();
-    }
+    private static void DebugMessageReceived(NetBuffer message) => logger.Debug(message.ReadString());
 
-    private static void WarningMessageReceived(NetBuffer message) {
-        Console.ForegroundColor = ConsoleColor.Yellow;
-        Console.WriteLine($"[WARN] {message.ReadString()}");
-        Console.ResetColor();
-    }
+    private static void WarningMessageReceived(NetBuffer message) => logger.Warn(message.ReadString());
 
-    private static void ErrorMessageReceived(NetBuffer message) {
-        Console.ForegroundColor = ConsoleColor.Red;
-        Console.WriteLine($"[ERROR] {message.ReadString()}");
-        Console.ResetColor();
-    }
+    private static void ErrorMessageReceived(NetBuffer message) => logger.Error(message.ReadString());
 }
diff --git a/CatsAreOnlineServer/src/MessageHandlers/StatusChangedMessageHandler.cs b/CatsAreOnlineServer/src/MessageHandlers/StatusChangedMessageHandler.cs
@@ -8,9 +8,17 @@
 
 using Lidgren.Network;
 
+using NLog;
+
 namespace CatsAreOnlineServer.MessageHandlers;
 
 public class StatusChangedMessageHandler {
+    private static readonly Logger logger = LogManager.GetCurrentClassLogger();
+    private static readonly Logger successLogger = logger.WithProperty("success", true);
+    private static readonly Logger progressLogger = logger.WithProperty("progress", true);
+    private static readonly Logger progressStartLogger = logger.WithProperty("progressStart", true);
+    private static readonly Logger unhandledLogger = logger.WithProperty("unhandled", true);
+
     public NetServer server { private get; init; }
     public Dictionary<NetConnection, Player> playerRegistry { private get; init; }
     public Dictionary<Guid, SyncedObject> syncedObjectRegistry { private get; init; }
@@ -29,30 +37,18 @@ public void MessageReceived(NetIncomingMessage message) {
         NetConnectionStatus status = (NetConnectionStatus)message.ReadByte();
 
         if(_messages.TryGetValue(status, out Action<NetIncomingMessage> action)) action(message);
-        else {
-            Console.ForegroundColor = ConsoleColor.DarkGray;
-            Console.WriteLine(
+        else
+            unhandledLogger.Info(
                 $"[UNHANDLED] {message.MessageType.ToString()} {status.ToString()} {message.ReadString()}");
-            Console.ResetColor();
-        }
     }
 
-    private static void RespondedAwaitingApprovalReceived(NetBuffer message) {
-        Console.ForegroundColor = ConsoleColor.DarkGray;
-        Console.WriteLine(message.ReadString());
-        Console.ResetColor();
-    }
+    private static void RespondedAwaitingApprovalReceived(NetBuffer message) =>
+        progressStartLogger.Info(message.ReadString());
 
-    private static void RespondedConnectReceived(NetBuffer message) {
-        Console.ForegroundColor = ConsoleColor.DarkGreen;
-        Console.WriteLine(message.ReadString());
-        Console.ResetColor();
-    }
+    private static void RespondedConnectReceived(NetBuffer message) => progressLogger.Info(message.ReadString());
 
     private void ConnectedReceived(NetIncomingMessage message) {
-        Console.ForegroundColor = ConsoleColor.Green;
-        Console.WriteLine(message.ReadString());
-        Console.ResetColor();
+        successLogger.Info(message.ReadString());
 
         foreach((NetConnection _, Player player) in playerRegistry) {
             if(player.connection != message.SenderConnection) continue;
@@ -85,4 +81,4 @@ private void DisconnectedReceived(NetBuffer message) {
             playerRegistry.Remove(connection);
         }
     }
-}
+}