From d4c149d5a2ec5c221fd999ef8afc9645b25c01ae Mon Sep 17 00:00:00 2001 From: beerpsi Date: Sun, 23 Jun 2024 12:38:34 +0700 Subject: [PATCH] feat(chuni): Improved logging --- core/logger/__init__.py | 11 ++--- core/logger/adapter.py | 46 +++++++++++++++++ titles/chuni/index.py | 106 ++++++++++++++++++++++++++-------------- titles/chuni/new.py | 2 +- 4 files changed, 120 insertions(+), 45 deletions(-) create mode 100644 core/logger/adapter.py diff --git a/core/logger/__init__.py b/core/logger/__init__.py index 7a47ba4..b948df1 100644 --- a/core/logger/__init__.py +++ b/core/logger/__init__.py @@ -3,8 +3,7 @@ import logging.handlers import os from typing import TYPE_CHECKING, Optional -import coloredlogs - +from .adapter import ExtraFormatter, MergedLoggerAdapter from .discord import DiscordLogHandler if TYPE_CHECKING: @@ -19,7 +18,7 @@ core_cfg: Optional["CoreConfig"] = None artemis_logger = logging.getLogger("artemis") log_fmt_str = "[%(asctime)s] %(title)s | %(levelname)s | %(message)s" -log_fmt = logging.Formatter(log_fmt_str) +log_fmt = ExtraFormatter(log_fmt_str) def init_root_logger(cfg: "CoreConfig"): @@ -54,7 +53,7 @@ def create_logger( logger = artemis_logger.getChild(logger_name) if getattr(logger, "initialized", False): - return logging.LoggerAdapter(logger, {"title": title}) + return MergedLoggerAdapter(logger, {"title": title}) if core_cfg is None: raise RuntimeError("Root logger has not been initialized.") @@ -71,6 +70,4 @@ def create_logger( logger.initialized = True - coloredlogs.install(level=level, logger=logger, fmt=log_fmt_str) - - return logging.LoggerAdapter(logger, {"title": title}) + return MergedLoggerAdapter(logger, {"title": title}) diff --git a/core/logger/adapter.py b/core/logger/adapter.py new file mode 100644 index 0000000..d622fc3 --- /dev/null +++ b/core/logger/adapter.py @@ -0,0 +1,46 @@ +from logging import Formatter, LogRecord, LoggerAdapter +from typing import TYPE_CHECKING + +if TYPE_CHECKING: + from typing import Any, MutableMapping + +# skip natural LogRecord attributes +# http://docs.python.org/library/logging.html#logrecord-attributes +RESERVED_ATTRS: set[str] = { + 'args', 'asctime', 'created', 'exc_info', 'exc_text', 'filename', + 'funcName', 'levelname', 'levelno', 'lineno', 'module', + 'msecs', 'message', 'msg', 'name', 'pathname', 'process', + 'processName', 'relativeCreated', 'stack_info', 'thread', 'threadName'} + + +class MergedLoggerAdapter(LoggerAdapter): + def process(self, msg: "Any", kwargs: "MutableMapping[str, Any]") -> tuple["Any", "MutableMapping[str, Any]"]: + kwargs["extra"] = {**self.extra, **kwargs.get("extra", {})} + + return msg, kwargs + + +class ExtraFormatter(Formatter): + def format(self, record: LogRecord): + s = super().format(record) + + extras = {} + + for key, value in record.__dict__.items(): + if key in {"title", "taskName"} or key in RESERVED_ATTRS or (hasattr(key, "startswith") and key.startswith("_")): + continue + + extras[key] = value + + if len(extras) == 0: + return s + + str_extras = str(extras) + + if len(str_extras) >= 300: + str_extras = str_extras[:297] + "..." + + s += " " + str_extras + + return s + diff --git a/titles/chuni/index.py b/titles/chuni/index.py index 2407e57..cc06ebf 100644 --- a/titles/chuni/index.py +++ b/titles/chuni/index.py @@ -1,6 +1,6 @@ from starlette.requests import Request from starlette.routing import Route -from starlette.responses import Response +from starlette.responses import PlainTextResponse, Response import zlib import yaml import json @@ -37,8 +37,9 @@ from .luminous import ChuniLuminous class ChuniServlet(BaseServlet): def __init__(self, core_cfg: CoreConfig, cfg_dir: str) -> None: super().__init__(core_cfg, cfg_dir) + self.game_cfg = ChuniConfig() - self.hash_table: Dict[Dict[str, str]] = {} + if path.exists(f"{cfg_dir}/{ChuniConstants.CONFIG_NAME}"): self.game_cfg.update( yaml.safe_load(open(f"{cfg_dir}/{ChuniConstants.CONFIG_NAME}")) @@ -69,6 +70,8 @@ class ChuniServlet(BaseServlet): logger_name="chuni", ) + self.hash_table: Dict[int, Dict[str, str]] = {} + for version, keys in self.game_cfg.crypto.keys.items(): if len(keys) < 3: continue @@ -78,7 +81,7 @@ class ChuniServlet(BaseServlet): method_list = [ method for method in dir(self.versions[version]) - if not method.startswith("__") + if method.startswith("handle_") and method.endswith("_request") ] for method in method_list: method_fixed = inflection.camelize(method)[6:-7] @@ -89,8 +92,17 @@ class ChuniServlet(BaseServlet): iter_count = 36 elif version == ChuniConstants.VER_CHUNITHM_SUN: iter_count = 70 - else: + elif version == ChuniConstants.VER_CHUNITHM_NEW_PLUS: + iter_count = 25 + elif version == ChuniConstants.VER_CHUNITHM_NEW: + iter_count = 54 + elif version == ChuniConstants.VER_CHUNITHM_PARADISE: iter_count = 44 + elif version == ChuniConstants.VER_CHUNITHM_CRYSTAL_PLUS: + iter_count = 67 + else: + self.logger.warn("v%d doesn't support encryption, or the iteration count is not known.", version) + continue hash = PBKDF2( method_fixed, @@ -104,7 +116,11 @@ class ChuniServlet(BaseServlet): self.hash_table[version][hashed_name] = method_fixed self.logger.debug( - f"Hashed v{version} method {method_fixed} with {bytes.fromhex(keys[2])} to get {hash.hex()}" + "Hashed v%d method %s with %s to get %s", + version, + method_fixed, + keys[2], + hashed_name, ) @classmethod @@ -144,7 +160,7 @@ class ChuniServlet(BaseServlet): req_raw = await request.body() - encrtped = False + encrypted = False internal_ver = 0 client_ip = Utils.get_ip_addr(request) @@ -195,25 +211,25 @@ class ChuniServlet(BaseServlet): elif version >= 130: internal_ver = ChuniConstants.VER_CHUNITHM_LUMINOUS - if all(c in string.hexdigits for c in endpoint) and len(endpoint) == 32: - # If we get a 32 character long hex string, it's a hash and we're - # doing encrypted. The likelyhood of false positives is low but - # technically not 0 + if (chuni_encoding := request.headers.get("chuni-encoding")) is not None: + # CRYSTAL PLUS/PARADISE forgot to hash the endpoint name in the User-Agent. if internal_ver < ChuniConstants.VER_CHUNITHM_NEW: endpoint = request.headers.get("User-Agent").split("#")[0] - else: if internal_ver not in self.hash_table: self.logger.error( - f"v{version} does not support encryption or no keys entered" + "v%d does not support encryption or no keys entered", + version, + extra={"chuni-encoding": chuni_encoding, "internal_ver": internal_ver}, ) - return Response(zlib.compress(b'{"stat": "0"}')) + return Response(zlib.compress(b'{"returnCode": "0"}')) elif endpoint.lower() not in self.hash_table[internal_ver]: self.logger.error( - f"No hash found for v{version} endpoint {endpoint}" + f"No hash found for v{version} endpoint {endpoint}", + extra={"chuni-encoding": chuni_encoding, "internal_ver": internal_ver}, ) - return Response(zlib.compress(b'{"stat": "0"}')) + return Response(zlib.compress(b'{"returnCode": "0"}')) endpoint = self.hash_table[internal_ver][endpoint.lower()] @@ -227,36 +243,44 @@ class ChuniServlet(BaseServlet): req_raw = crypt.decrypt(req_raw) except Exception as e: - self.logger.error( - f"Failed to decrypt v{version} request to {endpoint} -> {e}" + self.logger.exception( + f"Failed to decrypt v{version} request to {endpoint}", + exc_info=e, ) - return Response(zlib.compress(b'{"stat": "0"}')) + return Response(zlib.compress(b'{"returnCode": "0"}')) - encrtped = True + encrypted = True if ( - not encrtped + not encrypted and self.game_cfg.crypto.encrypted_only and internal_ver >= ChuniConstants.VER_CHUNITHM_CRYSTAL_PLUS ): self.logger.error( - f"Unencrypted v{version} {endpoint} request, but config is set to encrypted only: {req_raw}" + f"Unencrypted v{version} {endpoint} request, but config is set to encrypted only: {req_raw}", + extra={"internal_ver": internal_ver}, ) - return Response(zlib.compress(b'{"stat": "0"}')) + return Response(zlib.compress(b'{"returnCode": "0"}')) try: unzip = zlib.decompress(req_raw) except zlib.error as e: self.logger.warning( - f"Failed to decompress v{version} {endpoint} request -> {e}" + f"Failed to decompress v{version} {endpoint} request", + exc_info=e, ) - return Response(zlib.compress(b'{"stat": "0"}')) + return Response(zlib.compress(b'{"returnCode": "0"}')) req_data = json.loads(unzip) - self.logger.info(f"v{version} {endpoint} request from {client_ip}") - self.logger.debug(req_data) + self.logger.debug( + "Received request v%d %s from %s.", + version, endpoint, client_ip, + extra={ + "body": req_data, + }, + ) if game_code == "SDGS" and version >= 110: endpoint = endpoint.replace("C3Exp", "") @@ -267,28 +291,36 @@ class ChuniServlet(BaseServlet): func_to_find = "handle_" + inflection.underscore(endpoint) + "_request" handler_cls = self.versions[internal_ver](self.core_cfg, self.game_cfg) + handler = getattr(handler_cls, func_to_find, None) - if not hasattr(handler_cls, func_to_find): - self.logger.warning(f"Unhandled v{version} request {endpoint}") - resp = {"returnCode": 1} - + if handler is None: + if self.core_cfg.server.is_develop: + self.logger.warning(f"Unhandled v{version} request {endpoint}, returning stub response") + resp = {"returnCode": 1} + else: + self.logger.debug("(v%d %s) Returned 404.", version, endpoint) + return PlainTextResponse("Not Found", status_code=404) + else: try: - handler = getattr(handler_cls, func_to_find) resp = await handler(req_data) - except Exception as e: - self.logger.error(f"Error handling v{version} method {endpoint} - {e}") - return Response(zlib.compress(b'{"stat": "0"}')) + self.logger.exception("Error handling v%d method %s", version, endpoint, exc_info=e) - if resp == None: + if not self.core_cfg.server.is_develop: + self.logger.debug("(v%d %s) Returned 500.", version, endpoint) + return PlainTextResponse("Internal Server Error", status_code=500) + + resp = {"returnCode": 0} + + if resp is None: resp = {"returnCode": 1} - self.logger.debug(f"Response {resp}") + self.logger.debug("(v%d %s) Returned 200.", version, endpoint, extra=resp) zipped = zlib.compress(json.dumps(resp, ensure_ascii=False).encode("utf-8")) - if not encrtped: + if not encrypted: return Response(zipped) padded = pad(zipped, 16) diff --git a/titles/chuni/new.py b/titles/chuni/new.py index 02d9b51..12d04e7 100644 --- a/titles/chuni/new.py +++ b/titles/chuni/new.py @@ -20,7 +20,7 @@ class ChuniNew(ChuniBase): self.data = ChuniData(core_cfg) self.date_time_format = "%Y-%m-%d %H:%M:%S" self.logger = core.logger.create_logger("Chunithm", logger_name="chuni") - self.game = ChuniConstants.GAME_CODE + self.game = ChuniConstants.GAME_CODE_NEW self.version = ChuniConstants.VER_CHUNITHM_NEW def _interal_ver_to_intver(self) -> str: