feat(chuni): Improved logging

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 MergedLoggerAdapter(logger, {"title": title})
-
-    return logging.LoggerAdapter(logger, {"title": title})

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
+

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 (chuni_encoding := request.headers.get("chuni-encoding")) is not None:
-            # If we get a 32 character long hex string, it's a hash and we're
+            # CRYSTAL PLUS/PARADISE forgot to hash the endpoint name in the User-Agent.
-            # doing encrypted. The likelyhood of false positives is low but
-            # technically not 0
             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(
+                self.logger.exception(
-                    f"Failed to decrypt v{version} request to {endpoint} -> {e}"
+                    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(
-        self.logger.debug(req_data)
+            "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):
+        if handler is None:
-            self.logger.warning(f"Unhandled v{version} request {endpoint}")
+            if self.core_cfg.server.is_develop:
-            resp = {"returnCode": 1}
+                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}")
+                self.logger.exception("Error handling v%d method %s", version, endpoint, exc_info=e)
-                return Response(zlib.compress(b'{"stat": "0"}'))
 
-        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)

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: