diff --git a/core/logger.py b/core/logger.py new file mode 100644 index 0000000..003b73e --- /dev/null +++ b/core/logger.py @@ -0,0 +1,189 @@ +from __future__ import annotations +import logging +import os +import time +from bisect import bisect +from logging import ( + Filter, + Formatter, + LogRecord, + Logger, + StreamHandler, + FileHandler, +) + + +class Colors: + """ + ANSI color codes + https://gist.github.com/rene-d/9e584a7dd2935d0f461904b9f2950007 + """ + + BLACK = "\033[0;30m" + RED = "\033[0;31m" + GREEN = "\033[0;32m" + YELLOW = "\033[0;33m" + BLUE = "\033[0;34m" + MAGENTA = "\033[0;35m" + CYAN = "\033[0;36m" + WHITE = "\033[0;37m" + DARK_GRAY = "\033[0;90m" + + RESET = "\033[0m" + + +COLORS = Colors() +EXCEPTION_COLOR = COLORS.RED + +LOG_PATH = f"sc4mpserver-{time.strftime('%Y%m%d-%H%M%S')}.log" + +# Default date format for logged messages +DATE_FORMAT = "%H:%M:%S" + +# Default format for logged messages +# see https://docs.python.org/3/library/logging.html#logrecord-attributes +# {className} is a custom token and requires passing kw extra={'className': ... } to logging calls +# this is handled by instantiating class-specific LoggingAdapters in class __init__()s +# A custom filter sets a default value for logging calls without extra={} arg +DEFAULT_MSG = "[{asctime}] [SC4MP/{threadName}] ({className}) [{levelname}]" + +# Set log-level specific message format here. +BASE_FORMATS = { + logging.DEBUG: f"{DEFAULT_MSG} {{msg}}", + logging.INFO: f"{DEFAULT_MSG} {{msg}}", + logging.WARNING: f"{DEFAULT_MSG} {{msg}}", + logging.ERROR: f"{DEFAULT_MSG} {{msg}}", + logging.CRITICAL: f"{DEFAULT_MSG} {{msg}}", +} +# Set log-level colors here +LEVEL_COLORS = { + logging.DEBUG: COLORS.DARK_GRAY, + logging.INFO: COLORS.WHITE, + logging.WARNING: COLORS.YELLOW, + logging.ERROR: COLORS.MAGENTA, + logging.CRITICAL: COLORS.RED, +} +COLOR_FORMATS = { + level: f"{LEVEL_COLORS[level]}{BASE_FORMATS[level]}{COLORS.RESET}" + for level in BASE_FORMATS +} + + +class ColorExceptionFormatter(Formatter): + """ + Subclass of logging.Formatter which overides the formatException() and + formatStack(), and format() methods to optionally add formatting (color) to the output. + """ + + def __init__(self, *args, exc_color=None, **kwargs): + super().__init__(*args, **kwargs) + self.exc_color = exc_color + + def formatException(self, exc_info) -> str: + if not self.exc_color: + return super().formatException(exc_info) + return self.exc_color + super().formatException(exc_info) + COLORS.RESET + + def formatStack(self, stack_info: str) -> str: + if not self.exc_color: + return stack_info + return self.exc_color + stack_info + COLORS.RESET + + def format(self, record: LogRecord) -> str: + """ + Overridden here because the default implementation caches + the exception formatting which is not what we want. + """ + record.message = record.getMessage() + if self.usesTime(): + record.asctime = self.formatTime(record, self.datefmt) + s = self.formatMessage(record) + if record.exc_info: + record.exc_text = self.formatException(record.exc_info) + if record.exc_text: + if s[-1:] != "\n": + s = s + "\n" + s = s + record.exc_text + if record.stack_info: + if s[-1:] != "\n": + s = s + "\n" + s = s + self.formatStack(record.stack_info) + return s + + +class LevelFormatter(Formatter): + """ + Multi-level formatter from + https://stackoverflow.com/a/68154386/8098007 + """ + + def __init__(self, formats: dict[int, str], exc_color: str = None, **kwargs): + super().__init__() + + if "fmt" in kwargs: + raise ValueError( + "Format string must be passed to level-surrogate formatters, " + "not this one" + ) + + self.formats = sorted( + (level, ColorExceptionFormatter(fmt, exc_color=exc_color, **kwargs)) + for level, fmt in formats.items() + ) + self.exc_color = exc_color + + def format(self, record: LogRecord) -> str: + """Delegates the format call to a level-specific formatter""" + idx = bisect(self.formats, (record.levelno,), hi=len(self.formats) - 1) + level, formatter = self.formats[idx] + return formatter.format(record) + + +class ClassnameFilter(Filter): + """ + This (non)filter provides a default value for 'className' if the inspected + LogRecord does not have the attribute. + + Note: Python 3.10 adds a 'defaults' parameter to the Formatter class which + would make this unnecessary. + """ + + def filter(self, record: LogRecord) -> bool: + if not hasattr(record, "className"): + record.className = "" + return True + + +def build_logger(verbose: bool = False) -> Logger: + """Returns the custom sc4mp logger""" + # workaround to enable ANSI color in windows terminals + # https://stackoverflow.com/a/64222858/8098007 + os.system("") + + # build formatters + color_formatter = LevelFormatter( + formats=COLOR_FORMATS, exc_color=EXCEPTION_COLOR, datefmt=DATE_FORMAT, style="{" + ) + plain_formatter = LevelFormatter( + formats=BASE_FORMATS, datefmt=DATE_FORMAT, style="{" + ) + + # build handlers + terminal_handler = StreamHandler() + terminal_handler.setFormatter(color_formatter) + file_handler = FileHandler(LOG_PATH) + file_handler.setFormatter(plain_formatter) + + # build logger + logger = logging.getLogger(__name__) + logger.addHandler(file_handler) + logger.addHandler(terminal_handler) + logger.addFilter(ClassnameFilter()) + + # set log level + if verbose: + logger.setLevel("DEBUG") + else: + logger.setLevel("INFO") + + return logger diff --git a/sc4mpserver.py b/sc4mpserver.py index d83b1a8..6b0e3f2 100644 --- a/sc4mpserver.py +++ b/sc4mpserver.py @@ -19,11 +19,13 @@ from argparse import ArgumentParser, Namespace from collections import deque from datetime import datetime, timedelta +from logging import LoggerAdapter from pathlib import Path from typing import Iterable from core.config import * from core.dbpf import * +from core.logger import build_logger from core.util import * @@ -120,12 +122,15 @@ def main(): # Parse arguments args = parse_args() + # Create logger + logger = build_logger(verbose=args.verbose) + # Output sys.stdout = Logger() set_thread_name("Main", enumerate=False) # Title - report(SC4MP_TITLE) + logger.info(SC4MP_TITLE) # -s / --server-path argument global sc4mp_server_path @@ -143,10 +148,6 @@ def main(): else: sc4mp_nostart = False - # -v / --verbose argument - if args.verbose: - # TODO: use this flag to set logger level to debug once the logger PR is merged - pass # Server global sc4mp_server @@ -156,7 +157,7 @@ def main(): except Exception as e: - fatal_error(e) + logger.critical('Caught generic exception - fatal error', exc_info=True, stack_info=True) def parse_args() -> Namespace: @@ -296,12 +297,12 @@ def update_json(filename, data): def package_plugins_and_regions(): """TODO""" - report("Packaging plugins and regions...") + logger.info("Packaging plugins and regions...") - report("- packaging plugins...") + logger.info("- packaging plugins...") package("plugins") - report("- packaging regions...") + logger.info("- packaging regions...") package("regions") # Regions manager @@ -535,7 +536,7 @@ def send_or_cached(c, filename): def send_file(c, filename): """TODO""" - report("Sending file " + filename + "...") + logger.info(f"Sending file {filename}...") filesize = os.path.getsize(filename) c.sendall(str(filesize).encode()) @@ -557,8 +558,8 @@ def receive_file(c, filename, filesize): # # c.sendall(SC4MP_SEPARATOR) - report("Receiving " + str(filesize) + " bytes...") - report("writing to " + filename) + logger.info(f"Receiving {filesize} bytes...") + logger.info(f"writing to {filename}") if os.path.exists(filename): os.remove(filename) @@ -647,7 +648,7 @@ def restore(filename): else: if path[-5:] != ".json": raise ServerException("Backup file must be a \".json\" file.") - print("Restoring backup at \"" + path + "\"") + logger.info(f'Restoring backup at "{path}"') data = load_json(path) directory, filename = os.path.split(os.path.abspath(path)) files_entry = data["files"] @@ -656,12 +657,12 @@ def restore(filename): size = file_entry["size"] data_filename = os.path.join(directory, "data", hashcode + "_" + str(size)) restore_filename = os.path.join(directory, "restores", filename[:-5], original_filename) - print("Copying \"" + data_filename + "\" to \"" + restore_filename + "\"") + logger.info(f'Copying "{data_filename}" to "{restore_filename}"') restore_directory = os.path.split(restore_filename)[0] if not os.path.exists(restore_directory): os.makedirs(restore_directory) shutil.copy(data_filename, restore_filename) - print("- done.") + logger.info("- done.") return raise ServerException("File not found.") @@ -735,6 +736,9 @@ def __init__(self): super().__init__() + self.logger = LoggerAdapter(logger, + extra={'className': self.__class__.__name__}) + self.BIND_RETRY_DELAY = 5 #self.check_version() #TODO @@ -756,22 +760,21 @@ def run(self): global sc4mp_server_running, sc4mp_request_threads - report("Starting server...") + self.logger.info("Starting server...") - report("- creating socket...") + self.logger.info("- creating socket...") s = socket.socket() - report("- binding host " + SC4MP_HOST + " and port " + str(SC4MP_PORT) + "...") + self.logger.info(f"- binding host {SC4MP_HOST} and port {SC4MP_PORT}...") while True: try: s.bind((SC4MP_HOST, SC4MP_PORT)) break except OSError as e: - show_error(e) - print(f"[WARNING] - failed to bind socket, retrying in {self.BIND_RETRY_DELAY} seconds...") + self.logger.warning(f"failed to bind socket, retrying in {self.BIND_RETRY_DELAY} seconds...", exc_info=True) time.sleep(self.BIND_RETRY_DELAY) - report("- listening for connections...") + self.logger.info("- listening for connections...") s.listen(5) sc4mp_server_running = True @@ -798,15 +801,17 @@ def run(self): c.settimeout(sc4mp_config["PERFORMANCE"]["connection_timeout"]) + c.settimeout(sc4mp_config["PERFORMANCE"]["connection_timeout"]) + if (sc4mp_config["PERFORMANCE"]["request_limit"] is not None and host in client_requests and client_requests[host] >= sc4mp_config["PERFORMANCE"]["request_limit"]): - report("[WARNING] Connection blocked from " + str(host) + ":" + str(port) + ".") + logger.warning(f"Connection blocked from {host}:{port}.") c.close() continue else: client_requests.setdefault(host, 0) client_requests[host] += 1 - report("Connection accepted with " + str(host) + ":" + str(port) + ".") + self.logger.info(f"Connection accepted with {host}:{port}.") self.log_client(c) @@ -816,11 +821,11 @@ def run(self): except Exception as e: #socket.error as e: - show_error(e) + self.logger.exception("caught generic exception", stack_info=True) else: - print("[WARNING] Request thread limit reached!") + self.logger.warning("Request thread limit reached!") time.sleep(SC4MP_DELAY) @@ -828,12 +833,13 @@ def run(self): pass - report("Shutting down...") + logger.info("Shutting down...") sc4mp_server_running = False except Exception as e: - fatal_error(e) + logger.critical('Caught generic exception - fatal error', exc_info=True, stack_info=True) + sc4mp_server_running = False def log_client(self, c): @@ -895,7 +901,7 @@ def log_client(self, c): def create_subdirectories(self): """TODO""" - report("Creating subdirectories...") + self.logger.info("Creating subdirectories...") directories = ["_Backups", "_Database", "_Temp", "Plugins", "Regions"] @@ -907,7 +913,7 @@ def create_subdirectories(self): if (directory == "Plugins" or directory == "Regions"): shutil.unpack_archive(get_sc4mp_path(directory + ".zip"), new_directory) except Exception as e: - show_error(e) + self.logger.exception("caught generic exception", stack_info=True) #report("Failed to create " + directory + " subdirectory.", None, "WARNING") #report('(this may have been printed by error, check your sc4mp_server_path subdirectory)', None, "WARNING") @@ -918,7 +924,7 @@ def load_config(self): global sc4mp_config, SC4MP_CONFIG_PATH SC4MP_CONFIG_PATH = os.path.join(sc4mp_server_path, "serverconfig.ini") - report("Loading config...") + self.logger.info("Loading config...") sc4mp_config = Config(SC4MP_CONFIG_PATH, SC4MP_CONFIG_DEFAULTS, error_callback=show_error, update_constants_callback=update_config_constants) @@ -966,7 +972,7 @@ def load_config(self): def prep_database(self): """TODO""" - report("Preparing database...") + self.logger.info("Preparing database...") # Database directory database_directory = os.path.join(sc4mp_server_path, "_Database") @@ -1093,7 +1099,7 @@ def prep_database(self): def clear_temp(self): """TODO""" - report("Clearing temporary files...") + self.logger.info("Clearing temporary files...") try: purge_directory(os.path.join(sc4mp_server_path, "_Temp")) @@ -1107,7 +1113,7 @@ def prep_regions(self): if sc4mp_nostart: return - report("Preparing regions...") + self.logger.info("Preparing regions...") export("regions") @@ -1120,7 +1126,7 @@ def prep_regions(self): def prep_backups(self): """TODO""" - report("Preparing backups...") + self.logger.info("Preparing backups...") # Backups manager global sc4mp_backups_manager @@ -1154,7 +1160,7 @@ def prep_server_list(self): if not sc4mp_config["NETWORK"]["discoverable"]: return - report("Preparing server list...") + self.logger.info("Preparing server list...") global sc4mp_server_list sc4mp_server_list = ServerList() @@ -1171,6 +1177,9 @@ def __init__(self): self.backup_dir = Path(sc4mp_server_path) / "_Backups" super().__init__() + self.logger = LoggerAdapter(logger, + extra={'className': self.__class__.__name__}) + def run(self): """TODO""" @@ -1210,7 +1219,8 @@ def run(self): except Exception as e: - fatal_error(e) + logger.critical('Caught generic exception - fatal error', exc_info=True, stack_info=True) + sc4mp_server_running = False def load_json(self, filename): @@ -1240,7 +1250,7 @@ def backup(self): #TODO stop backing up the backups subdirectory show_error("An error occured while pruning backups.") # Report creating backups - report("Creating backup...", self) + self.logger.info("Creating backup...") # Loop through all files in server directory and append them to a list fullpaths = [] @@ -1261,7 +1271,7 @@ def backup(self): #TODO stop backing up the backups subdirectory os.makedirs(directory) filename = os.path.join(directory, hashcode + "_" + str(filesize)) if not os.path.exists(filename) or hashcode != md5(filename) or filesize != os.path.getsize(filename): - report('- copying "' + fullpath + '"...', self) + self.logger.info(f'- copying "{fullpath}"...') if os.path.exists(filename): os.remove(filename) shutil.copy(fullpath, filename) @@ -1280,7 +1290,7 @@ def backup(self): #TODO stop backing up the backups subdirectory self.update_json(backup_filename, backup_data) # Report done - report("- done.", self) + self.logger.info("- done.") def prune(self) -> None: @@ -1354,6 +1364,9 @@ def __init__(self, filename): """TODO""" super().__init__() + + self.logger = LoggerAdapter(logger, + extra={'className': self.__class__.__name__}) self.filename = filename #os.path.join(sc4mp_server_path, "_Database", "users.json") self.data = self.load_json(self.filename) @@ -1381,16 +1394,17 @@ def run(self): time.sleep(SC4MP_DELAY) new_data = str(self.data) if old_data != new_data: - report('Updating "' + self.filename + '"...', self) + self.logger.info(f'Updating "{self.filename}"...') self.update_json(self.filename, self.data) - report("- done.", self) + self.logger.info("- done.") old_data = new_data except Exception as e: - show_error(e) + self.logger.exception("caught generic exception", stack_info=True) except Exception as e: - fatal_error(e) + logger.critical('Caught generic exception - fatal error', exc_info=True, stack_info=True) + sc4mp_server_running = False def load_json(self, filename): @@ -1419,6 +1433,9 @@ def __init__(self): super().__init__() + self.logger = LoggerAdapter(logger, + extra={'className': self.__class__.__name__}) + self.regions_modified = False self.export_regions = False self.tasks = [] @@ -1452,11 +1469,11 @@ def run(self): # Export regions if requested, otherwise check for new tasks if self.export_regions: - report("Exporting regions as requested...", self) + self.logger.info("Exporting regions as requested...") export("regions") - report("- done.", self) + self.logger.info("- done.") self.regions_modified = False self.export_regions = False @@ -1472,7 +1489,7 @@ def run(self): # Read values from tuple save_id, user_id, region, savegame = task - report('Processing task "' + save_id + '"...', self) + self.logger.info(f'Processing task "{save_id}"...') # Another layer of exception handling so that the request handler isn't waiting around in the event of an error try: @@ -1585,7 +1602,7 @@ def run(self): # Raise the exception so that it appears in the server's output raise e - report("- done.", self) + self.logger.info("- done.") else: @@ -1609,11 +1626,12 @@ def run(self): except Exception as e: - show_error(e) + self.logger.exception("caught generic exception", stack_info=True) except Exception as e: - fatal_error(e) + logger.critical('Caught generic exception - fatal error', exc_info=True, stack_info=True) + sc4mp_server_running = False def load_json(self, filename): @@ -1738,7 +1756,10 @@ def __init__(self, c): """TODO""" super().__init__() - + + self.logger = LoggerAdapter(logger, + extra={'className': self.__class__.__name__}) + self.c = c @@ -1759,7 +1780,7 @@ def run(self): request = args[0] - report("Request: " + request, self) + self.logger.info(f"Request: {request}") if request == "ping": self.ping(c) @@ -1824,13 +1845,14 @@ def run(self): except Exception as e: - show_error(e) + self.logger.exception("caught generic exception", stack_info=True) sc4mp_request_threads -= 1 except Exception as e: - fatal_error(e) + logger.critical('Caught generic exception - fatal error', exc_info=True, stack_info=True) + sc4mp_server_running = False def request_header(self, c, args): @@ -2038,7 +2060,7 @@ def save(self, c): savegame.get_SC4ReadRegionalCity() # Filter out tiles that do not border every other tile - report("Savegame filter 1", self) + logger.debug("Savegame filter 1") new_savegames = [] for savegame in savegames: add = True @@ -2064,14 +2086,14 @@ def save(self, c): add = False if add: new_savegames.append(savegame) - report("YES (" + str(savegameX) + ", " + str(savegameY) + ")", self) + self.logger.debug(f"YES ({savegameX}, {savegameY})") else: - report("NO (" + str(savegameX) + ", " + str(savegameY) + ")", self) + self.logger.debug(f"NO ({savegameX}, {savegameY})") savegames = new_savegames # Filter out tiles which have identical date subfiles as their previous versions if len(savegames) > 1: - report("Savegame filter 2", self) + self.logger.debug("Savegame filter 2") new_savegames = [] for savegame in savegames: savegameX = savegame.SC4ReadRegionalCity["tileXLocation"] @@ -2084,16 +2106,16 @@ def save(self, c): new_date_subfile_hash = file_md5(savegame.decompress_subfile("2990c1e5")) if new_date_subfile_hash not in date_subfile_hashes: new_savegames.append(savegame) - report("YES (" + str(savegameX) + ", " + str(savegameY) + ")", self) + self.logger.debug(f"YES ({savegameX}, {savegameY})") else: - report("NO (" + str(savegameX) + ", " + str(savegameY) + ")", self) + self.logger.debug(f"NO ({savegameX}, {savegameY})") else: new_savegames.append(savegame) - report("YES (" + str(savegameX) + ", " + str(savegameY) + ")", self) + self.logger.debug(f"YES ({savegameX}, {savegameY})") savegame = None savegames = new_savegames else: - report("Skipping savegame filter 2", self) + self.logger.debug("Skipping savegame filter 2") # If one savegame remains, pass it to the regions manager, otherwise report to the client that the save push is invalid if len(savegames) == 1: @@ -2296,6 +2318,9 @@ def __init__(self): super().__init__() + self.logger = LoggerAdapter(logger, + extra={'className': self.__class__.__name__}) + self.SERVER_LIMIT = 1 + len(SC4MP_SERVERS) + 100 #TODO make configurable try: @@ -2340,7 +2365,7 @@ def run(self): server_id = random.choice(list(self.servers.keys())) server_entry = self.servers.pop(server_id) server = (server_entry["host"], server_entry["port"]) - print("Synchronizing server list with " + server[0] + ":" + str(server[1]) + "...") + self.logger.debug(f"Synchronizing server list with {server[0]}:{server[1]}...") # Ping the next server try: @@ -2350,33 +2375,33 @@ def run(self): # Skip it if it matches the server id of this server if server_id == sc4mp_config["INFO"]["server_id"]: - print("- \"" + server_id + "\" is our server_id!") + self.logger.debug(f'- "{server_id}" is our server_id!') continue # Resolve server id confilcts if server_id in self.servers: - print("- \"" + server_id + "\" already found in our server list") + self.logger.debug(f' - "{server_id}" already found in our server list') old_server = (self.servers[server_id]["host"], self.servers[server_id]["port"]) if server != old_server: - print("[WARNING] Resolving server_id conflict...") + self.logger.warning(" - Resolving server_id conflict...") if self.ping(old_server) is None: - print("[WARNING] - keeping the new server!") + self.logger.warning(" - keeping the new server!") self.servers[server_id] = {"host": server[0], "port": server[1]} else: - print("[WARNING] - keeping the old server!") + self.logger.warning(" - keeping the old server!") else: - print("- adding \"" + server_id + "\" to our server list") + self.logger.debug(f' - adding "{server_id}" to our server list') self.servers[server_id] = {"host": server[0], "port": server[1]} # Request to be added to the server's server list - print("- requesting to be added to their server list...") + self.logger.debug(" - requesting to be added to their server list...") self.add_server(server) # Get the server's server list - print("- receiving their server list...") + self.logger.debug(" - receiving their server list...") self.server_list(server) - print("- done.") + self.logger.debug(" - done.") except Exception as e: @@ -2391,7 +2416,7 @@ def run(self): except Exception as e: - show_error(e) + self.logger.exception("caught generic exception", stack_info=True) def create_socket(self, server):