Merge pull request #4 from BreathXV/debug-logging

Debug logging

components/check_player.py

@@ -2,6 +2,8 @@
 import json
 import logging
 
+from components import logging as dev
+
 logger = logging.getLogger(__name__)
 
 
@@ -27,6 +29,7 @@ def is_player_in_database(player_name: str, identity_id: str, db_path: str) -> b
     try:
         with sqlite3.connect(db_path) as conn:
             cur = conn.cursor()
+            dev.debugLine("Established connection with database.")
             cur.execute(
                 """
                 SELECT whitelisted 
@@ -37,6 +40,7 @@ def is_player_in_database(player_name: str, identity_id: str, db_path: str) -> b
                 (player_name, identity_id),
             )
             is_whitelisted = cur.fetchone()
+            dev.debugLine("Fetched whitelist data for user from database.")
             if is_whitelisted is not None:
                 logger.info(
                     f"Player {player_name} or IdentityId {identity_id} found in database and is whitelisted."
@@ -74,6 +78,7 @@ def is_player_in_json(player_name: str, identity_id: str, json_path: str) -> boo
     try:
         with open(json_path, "r", encoding="utf-8") as file:
             data = json.load(file)
+            dev.debugLine("Loaded JSON.")
             for player in data.get("players", []):
                 if (
                     player_name.lower() == player.get("game_name", "").lower()

components/config.py

@@ -1,5 +1,8 @@
 import json
 import logging
+import sys
+
+from components import logging as dev
 
 logger = logging.getLogger(__name__)
 
@@ -67,6 +70,7 @@ def check_config(self) -> bool:
                 logger.info("Loaded configuration file")
                 # Check for all params in the config
                 for param in self.param_dict.keys():
+                    dev.debugLine("Checking params in dictionary at line")
                     if param not in config:
                         logger.error(
                             f"A parameter '{param}' is missing in the configuration file!"
@@ -77,10 +81,11 @@ def check_config(self) -> bool:
         except FileNotFoundError:
             logger.error(f"Configuration file could not be found at {self.config_path}")
             return False
-        except json.JSONDecodeError:
+        except json.JSONDecodeError as e:
             logger.error(
                 f"File was found but could not decode it - make sure it has 'utf-8' encoding."
             )
+            dev.debugLine(e.msg)
             return False
 
     def get_config_value(self) -> bool:
@@ -97,6 +102,7 @@ def get_config_value(self) -> bool:
                 # Assign each config value to the corresponding class attribute
                 logger.info("Assigning all config values...")
                 for param in self.param_dict.keys():
+                    dev.debugLine("Assigning parameters to class attributes.")
                     if param in config:
                         setattr(self, param, config[param])
                         logger.info(f"{param}: {getattr(self, param)}")
@@ -109,8 +115,9 @@ def get_config_value(self) -> bool:
         except FileNotFoundError:
             logger.error(f"Configuration file could not be found at {self.config_path}")
             return False
-        except json.JSONDecodeError:
+        except json.JSONDecodeError as e:
             logger.error(
                 f"File was found but could not decode it - make sure it has 'utf-8' encoding."
             )
+            dev.debugLine(e.msg)
             return False

components/heartbeat.py

@@ -1,6 +1,8 @@
 import time
 import logging
 
+from components import logging as dev
+
 logger = logging.getLogger(__name__)
 
 
@@ -17,3 +19,4 @@ def heartbeat(count: int) -> None:
     while True:
         logger.info("Whitelist is running... Use [Ctrl + C] to stop the application.")
         time.sleep(count)
+        dev.debugLine(f"Sleep set to: {str(count)}")

components/initiate.py

@@ -2,6 +2,7 @@
 import logging
 
 from components.process_logs import find_latest_log_dir, tail_log_file, process_log_line
+from components import logging as dev
 
 logger = logging.getLogger(__name__)
 
@@ -40,13 +41,18 @@ def initiate(
     heartbeat_thread = threading.Thread(
         target=heartbeat(heartbeat), name="HeartbeatThread"
     )
+    dev.debugLine("Created heartbeat thread.")
     heartbeat_thread.daemon = True
+    dev.debugLine("Added thread to daemon.")
     heartbeat_thread.start()
+    dev.debugLine("Started heartbeat thread.")
 
     latest_console_log_path = find_latest_log_dir(base_log_dir)
+    dev.debugLine("Console directory log path assigned.")
 
     try:
         if latest_console_log_path:
+            dev.debugLine("Starting log processing on console log path...")
             tail_log_file(
                 latest_console_log_path,
                 lambda line: process_log_line(
@@ -60,6 +66,7 @@ def initiate(
             )
         else:
             logger.error("No recent log file found to process.")
+            dev.debugLine(f"Console Log Path: {latest_console_log_path}")
     except KeyboardInterrupt:
         logger.info("Script interrupted by user.")
     except Exception as e:

components/kick_player.py

@@ -3,6 +3,8 @@
 
 from rcon.battleye import Client
 
+from components import logging as dev
+
 logger = logging.getLogger(__name__)
 
 
@@ -28,28 +30,33 @@ def execute_kick_command(
     def kick_player() -> None:
         """Nested function that establishes a connection with BERCon and executes the kick command."""
         command = f"#kick {player_id}"
+        dev.debugLine(f"Command values assigned: {command}")
 
         try:
             with Client(host=rcon_host, port=rcon_port, passwd=rcon_password) as client:
                 rsp = client.run(command=command)
                 if rsp == "":
                     logger.error(f"Failed to execute kick command for player ID {player_id}")
-                    logger.debug(
+                    dev.debugLine(
                         f"""
-                        Response: {rsp} | Command: {command} | 
-                        Host: {rcon_host} | Port: {rcon_port} | Password: {rcon_password}
+                        Response: {rsp}\n
+                        Command: {command}\n 
+                        Host: {rcon_host}\n
+                        Port: {rcon_port}\n
+                        Password: {rcon_password}
                         """
                     )
                 # TODO: Add additional error handling for other rsp
                 client.close()
             logger.info(
-                "Successfully executed kick command for player ID %s" % player_id
+                f"Successfully executed kick command for player ID {player_id}"
             )
         except Exception as e:
             logger.error(
-                "Unexpected error executing kick command for player ID %s: %s"
-                % (player_id, e)
+                f"Unexpected error executing kick command for player ID {player_id}: {e}"
             )
 
     kick_thread = threading.Thread(target=kick_player, name=f"KickThread-{player_id}")
+    dev.debugLine("Created kick thread.")
     kick_thread.start()
+    dev.debugLine("Started kick thread.")

components/logging.py

@@ -1,5 +1,8 @@
 import logging, logging.handlers
 import os  # TODO: Change to pathlib
+import sys
+
+logger = logging.getLogger(__name__)
 
 
 def setup_logging(log_directory: str) -> None:
@@ -26,3 +29,6 @@ def setup_logging(log_directory: str) -> None:
     console_handler.setFormatter(console_formatter)
 
     logging.basicConfig(level=logging.INFO, handlers=[file_handler, console_handler])
+
+def debugLine(msg: str) -> None:
+    logger.debug(f"Debug: {msg}: @{sys._getframe().f_back.f_lineno}")

components/process_logs.py

@@ -6,6 +6,7 @@
 
 from components.check_player import is_player_in_json, is_player_in_database
 from components.kick_player import execute_kick_command
+from components import logging as dev
 
 logger = logging.getLogger(__name__)
 
@@ -25,6 +26,7 @@ def tail_log_file(file_path: str, callback: callable) -> None:
     try:
         with open(file_path, "r", encoding="utf-8") as log_file:
             log_file.seek(0, 2)
+            dev.debugLine("Found file, seeking last two lines...")
             while True:
                 chunk = log_file.read(1024)
                 if not chunk:
@@ -33,7 +35,7 @@ def tail_log_file(file_path: str, callback: callable) -> None:
                 for line in chunk.splitlines():
                     callback(line)
     except FileNotFoundError:
-        logger.error("Log file not found: %s" % file_path)
+        logger.error(f"Log file not found: {file_path}")
     except Exception:
         logger.exception("Error reading log file")
 
@@ -73,13 +75,12 @@ def process_log_line(
         action, player_id, player_name, identity_id = match.groups()
         player_name = player_name.strip()
         logger.info(
-            "%s Player - ID: %s, Name: %s, IdentityId: %s"
-            % (
-                action,
-                player_id,
-                player_name,
-                identity_id,
-            )
+            f"""
+            {action} 
+            Player - ID: {player_id}, 
+            Name: {player_name}, 
+            IdentityId: {identity_id}
+            """
         )
 
         if whitelist_type == "database":
@@ -89,28 +90,23 @@ def process_log_line(
         elif whitelist_type == "json":
             is_whitelisted = is_player_in_json(player_name, identity_id, whitelist_path)
         else:
-            logger.error("Unknown whitelist type: %s" % whitelist_type)
+            logger.error(f"Unknown whitelist type: {whitelist_type}")
             return
 
         if not is_whitelisted:
             logger.warning(
-                "Player: %s with IdentityId: %s is NOT whitelisted! Kicking..."
-                % (
-                    player_name,
-                    identity_id,
-                )
+                f"""
+                Player: {player_name} with IdentityId: {identity_id} is NOT whitelisted! Kicking...
+                """
             )
+            dev.debugLine("Executing kick command shortly!")
             execute_kick_command(player_id, rcon_host, rcon_port, rcon_password)
         else:
             logger.info(
-                "Player: %s with IdentityId: %s is whitelisted!"
-                % (
-                    player_name,
-                    identity_id,
-                )
+                f"Player: {player_name} with IdentityId: {identity_id} is whitelisted!"
             )
     else:
-        logger.debug("Unmatched line: %s" % line)
+        dev.debugLine(f"Unmatched line: {line}")
 
 
 def find_latest_log_dir(base_log_dir: str) -> str | None:
@@ -124,13 +120,15 @@ def find_latest_log_dir(base_log_dir: str) -> str | None:
         The directory where the game's `console.log` file is based.
     """
     dir_pattern = re.compile(r"logs_\d{4}-\d{2}-\d{2}_\d{2}-\d{2}-\d{2}")
+    dev.debugLine("Compiled regex pattern.")
     log_dirs = [
         d
         for d in os.listdir(base_log_dir)
         if os.path.isdir(os.path.join(base_log_dir, d)) and dir_pattern.match(d)
     ]
 
     if not log_dirs:
+        dev.debugLine("Could not find console log directory.")
         return None
 
     latest_log_dir = max(

main.py

@@ -4,6 +4,7 @@
 from components.logging import setup_logging
 from components.config import Config
 from components.initiate import initiate
+from components import logging as dev
 
 logger = logging.getLogger(__name__)
 
@@ -18,6 +19,7 @@ def main() -> None:
                     https://github.com/BreathXV/ReforgerWhitelistPy
                     """,
     )
+    dev.debugLine("Added argument parser.")
     parser.add_argument(
         "--cfg",
         "--config",
@@ -26,6 +28,7 @@ def main() -> None:
         help="Start from a config.json",
         dest="config",
     )
+    dev.debugLine("Added config argument to parser.")
     # parser.add_argument(
     #     "--wt",
     #     "--whitelist-type",
@@ -42,6 +45,7 @@ def main() -> None:
         help="Use JSON for whitelist queries.",
         dest="json",
     )
+    dev.debugLine("Added json argument to parser.")
     parser.add_argument(
         "--db",
         "--database",
@@ -50,6 +54,7 @@ def main() -> None:
         help="Use a database for whitelist queries.",
         dest="db",
     )
+    dev.debugLine("Added database argument to parser.")
     parser.add_argument(
         "--wp",
         "--whitelist-path",
@@ -58,6 +63,7 @@ def main() -> None:
         help="Path to the whitelist file (database or JSON).",
         dest="whitelist_path",
     )
+    dev.debugLine("Added whitelist path argument to parser.")
     parser.add_argument(
         "--bl",
         "--base-log-dir",
@@ -66,6 +72,7 @@ def main() -> None:
         help="Base directory to look for log files.",
         dest="base_log_dir",
     )
+    dev.debugLine("Added base log directory argument to parser.")
     parser.add_argument(
         "--rh",
         "--rcon-host",
@@ -74,6 +81,7 @@ def main() -> None:
         help="RCON host address.",
         dest="rcon_host",
     )
+    dev.debugLine("Added rcon host argument to parser.")
     parser.add_argument(
         "--rp",
         "--rcon-port",
@@ -82,6 +90,7 @@ def main() -> None:
         help="RCON port number.",
         dest="rcon_port",
     )
+    dev.debugLine("Added rcon port argument to parser.")
     parser.add_argument(
         "--rpw",
         "--rcon-password",
@@ -90,6 +99,7 @@ def main() -> None:
         help="RCON password.",
         dest="rcon_password",
     )
+    dev.debugLine("Added rcon password argument to parser.")
     parser.add_argument(
         "--hb",
         "--heartbeat",
@@ -99,8 +109,10 @@ def main() -> None:
         help="Interval in seconds when the application should log it's alive.",
         dest="heartbeat",
     )
+    dev.debugLine("Added heartbeat argument to parser.")
 
     args = parser.parse_args()
+    dev.debugLine("Parsing all arguments.")
 
     if args.json:
         converted_whitelist_type = "json"