Add some logging action

TODO.txt

@@ -1 +1,2 @@
-- Implement proper logging (is there some sort of flask logging, or should I just log to a file?)
+- Logging is implemented, so lets throw some logs around perhaps
+- Fix the issue where the log directory probably shouldn't be a relative path

v8_server/__init__.py

@@ -1,8 +1,10 @@
+import logging
 import os
+from logging.config import dictConfig
 from pathlib import Path
 from typing import Optional, Union
 
-from flask import Flask
+from flask import Flask, has_request_context, request
 
 from v8_server.config import Development, Production
 from v8_server.utils.flask import generate_secret_key
@@ -10,6 +12,85 @@ from v8_server.utils.flask import generate_secret_key
 from .version import __version__
 
 
+class RequestFormatter(logging.Formatter):
+    def format(self, record):
+        encrypted = "None"
+        compressed = "None"
+        method = None
+
+        if has_request_context():
+            method = request.method
+            headers = request.headers
+
+            if "x-eamuse-info" in headers:
+                encrypted = headers["x-eamuse-info"]
+            if "x-compress" in headers:
+                compressed = headers["x-compress"]
+
+        record.encrypted = encrypted
+        record.compressed = "None" if compressed == "none" else compressed
+        record.method = method
+
+        return super().format(record)
+
+
+# Define the logger
+dictConfig(
+    {
+        "version": 1,
+        "formatters": {
+            "default": {
+                "format": "[ %(asctime)s | %(levelname)-8s | %(name)s ]\n%(message)s"
+            },
+            "detailed": {
+                "()": RequestFormatter,
+                "format": (
+                    "[ %(asctime)s | %(levelname)-8s | %(method)-4s | %(encrypted)-15s "
+                    "| %(compressed)-4s | %(name)s ]\n%(message)s"
+                ),
+            },
+        },
+        "handlers": {
+            "wsgi": {
+                "class": "logging.StreamHandler",
+                "stream": "ext://flask.logging.wsgi_errors_stream",
+                "formatter": "default",
+            },
+            "debugfile": {
+                "class": "logging.handlers.TimedRotatingFileHandler",
+                "filename": "logs/debug.log",
+                "formatter": "default",
+                "when": "midnight",
+            },
+            "requestsfile": {
+                "class": "logging.handlers.TimedRotatingFileHandler",
+                "filename": "logs/requests.log",
+                "formatter": "detailed",
+                "when": "midnight",
+            },
+            "allfile": {
+                "class": "logging.handlers.TimedRotatingFileHandler",
+                "filename": "logs/all.log",
+                "formatter": "detailed",
+                "when": "midnight",
+            },
+            "werkzeugfile": {
+                "class": "logging.handlers.TimedRotatingFileHandler",
+                "filename": "logs/werkzeug.log",
+                "formatter": "detailed",
+                "when": "midnight",
+            },
+        },
+        "loggers": {
+            "": {"handlers": ["wsgi", "allfile"]},
+            "v8_server": {"level": "DEBUG", "handlers": ["debugfile"]},
+            "requests": {"level": "DEBUG", "handlers": ["requestsfile"]},
+            "werkzeug": {"level": "DEBUG", "handlers": ["werkzeugfile"]},
+        },
+    }
+)
+logging.getLogger("").setLevel(logging.INFO)
+
 # Set the proper config values
 config: Optional[Union[Production, Development]] = None
 if os.environ.get("ENV", "dev") == "prod":

v8_server/utils/xml.py

@@ -1,3 +1,4 @@
+import logging
 from binascii import unhexlify
 from pathlib import Path
 from random import randint
@@ -14,6 +15,9 @@ from v8_server.utils.eamuse import get_timestamp
 from v8_server.utils.lz77 import Lz77
 
 
+logger = logging.getLogger(__name__)
+rlogger = logging.getLogger("requests")
+
 EAMUSE_CONFIG = {"encrypted": False, "compressed": False}
 REQUESTS_PATH = Path("./requests")
 
@@ -52,19 +56,15 @@ def eamuse_read_xml(request: Request) -> Tuple[str, str, str, str, str]:
     with output_filename.open("w") as f:
         f.write(xml_text.decode("UTF-8"))
 
-    model = root.attrib["model"]
-    module = root[0].tag
-    method = root[0].attrib["method"] if "method" in root[0].attrib else None
-    command = root[0].attrib["command"] if "command" in root[0].attrib else None
+    model = str(root.attrib["model"])
+    module = str(root[0].tag)
+    method = str(root[0].attrib["method"] if "method" in root[0].attrib else None)
+    command = str(root[0].attrib["command"] if "command" in root[0].attrib else None)
 
-    print(
-        "---- Read Request ----\n"
-        f"Headers: [{dict(headers)}]\n"
-        f"  Model: [{model}]\n"
-        f" Module: [{module}]\n"
-        f" Method: [{method}]\n"
-        f"Command: [{command}]\n"
-        "   Data:\n"
+    rlogger.debug(
+        "---- Request ----\n"
+        f"[ {'Model':^20} | {'Module':^15} | {'Method':^15} | {'Command':^20} ]\n"
+        f"[ {model:^20} | {module:^15} | {method:^15} | {command:^20} ]\n"
         f"{xml_text.decode('UTF-8')[:-1]}\n"
     )
 
@@ -110,11 +110,9 @@ def eamuse_prepare_xml(xml: str) -> Tuple[bytes, Dict[str, str]]:
     else:
         data = xml_bin
 
-    print(
-        "---- Write Response ----\n"
-        "   Data: [\n"
+    rlogger.debug(
+        "---- Response ----\n"
         f"{ET.tostring(xml_root, pretty_print=True).decode('UTF-8')[:-1]}\n"
-        f"Headers: [{headers}]\n"
     )
 
     return data, headers

v8_server/view/index.py

@@ -15,16 +15,21 @@ def catch_all(path: str) -> str:
     This is currently my catch all route, for whenever a new endpoint pops up that isn't
     implemented
     """
-    d = f"""
-        {request.args!r}
-        {request.form!r}
-        {request.files!r}
-        {request.values!r}
-        {request.json!r}
-        {request.data!r}
-        {request.headers!r}
-    """
-    print(d)
+    headers = request.headers
+
+    header_str = ""
+    for header in headers:
+        header_str += f"{header[0]:>15}: {header[1]}\n"
+
+    args = "None" if len(request.args) == 0 else request.args
+    data = request.data
+    d = (
+        "*** Unknown Request ***\n"
+        f"           Args: {args}\n"
+        f"    Data Length: {len(data)}\n"
+        f"{header_str[:-1]}\n"
+    )
+    app.logger.debug(d)
     return "You want path: %s" % path
 
 
@@ -140,6 +145,11 @@ def package() -> Tuple[bytes, Dict[str, str]]:
 
 @app.route("/local/service", methods=["POST"])
 def local() -> Tuple[bytes, Dict[str, str]]:
+    """
+    This is probably a big chunk of implementation. Handle all "local" service requests
+    which might have a whole bunch of stuff going on
+    """
+
     xml, model, module, method, command = eamuse_read_xml(request)
 
     if module == "shopinfo":
@@ -155,7 +165,7 @@ def local() -> Tuple[bytes, Dict[str, str]]:
             )
     elif module == "demodata":
         if method == "get":
-            response = E.response()
+            response = E.response(E.demodata())
     else:
         response = base_response(module)